9.0 Performance Tracing - Leverage the data

Ask general questions here.
dhale
Posts: 21
Joined: Thu Feb 27, 2014 7:33 pm

9.0 Performance Tracing - Leverage the data

Post by dhale » Mon Feb 25, 2019 5:17 pm

Wondering if anyone has had a chance to look at the performance tracing in 9.0 yet?

I was just reading over https://www.ranorex.com/help/latest/ran ... roduction/
and had some questions about it - specifically the leverage the data part about "Time-by-repository-item evaluation".

Since no sample xls is provided, I cant make out what it is that they are doing exactly.

User avatar
N612
Posts: 80
Joined: Mon Jul 11, 2016 4:01 pm

Re: 9.0 Performance Tracing - Leverage the data

Post by N612 » Tue Feb 26, 2019 8:27 pm

There are several CSV files output when all 'tracers' are enabled. Below are the first five lines of each output to give you a better idea of what they contain. With a little Excel sorting/conditional highlighting, you can quickly see where there may be some room for performance improvements.

PerfTracing_Overall_<DateTimeStamp>.csv

Code: Select all

+-----------------------------+---------------+----------+------------------+------------+-----------+
| TimeStamp                   | TestContainer | Module   | EventType        | Details    | TotalTime |
+-----------------------------+---------------+----------+------------------+------------+-----------+
| 2019-02-26T14:06:24.4430566 | AddNewEntry   | StartSUT | screenshot-trace | Foreground | 50        |
+-----------------------------+---------------+----------+------------------+------------+-----------+
| 2019-02-26T14:06:24.4410568 | AddNewEntry   | StartSUT | report-slow      | Info:Data  | 11        |
+-----------------------------+---------------+----------+------------------+------------+-----------+
| 2019-02-26T14:06:24.4520568 | AddNewEntry   | StartSUT | other            |            | 69        |
+-----------------------------+---------------+----------+------------------+------------+-----------+
| 2019-02-26T14:06:24.5217227 | AddNewEntry   | StartSUT | screenshot-trace | Foreground | 34        |
+-----------------------------+---------------+----------+------------------+------------+-----------+

PerfTracing_Misc_<DateTimeStamp>.csv

Code: Select all

+-----------------------------+-----------------------------------------------------------+------------------+-------------------------------------------------------------------------------------------------------------------------------+-----------+
| TimeStamp                   | Module                                                    | EventType        | Details                                                                                                                       | TotalTime |
+-----------------------------+-----------------------------------------------------------+------------------+-------------------------------------------------------------------------------------------------------------------------------+-----------+
| 2019-02-26T14:06:24.4430566 | KeePassTestSuite\AddNewEntry\Setup\StartAndLogin\StartSUT | screenshot-trace | Foreground                                                                                                                    | 50        |
+-----------------------------+-----------------------------------------------------------+------------------+-------------------------------------------------------------------------------------------------------------------------------+-----------+
| 2019-02-26T14:06:24.4410568 | KeePassTestSuite\AddNewEntry\Setup\StartAndLogin\StartSUT | report-slow      | Info:Data                                                                                                                     | 11        |
+-----------------------------+-----------------------------------------------------------+------------------+-------------------------------------------------------------------------------------------------------------------------------+-----------+
| 2019-02-26T14:06:24.5217227 | KeePassTestSuite\AddNewEntry\Setup\StartAndLogin\StartSUT | screenshot-trace | Foreground                                                                                                                    | 34        |
+-----------------------------+-----------------------------------------------------------+------------------+-------------------------------------------------------------------------------------------------------------------------------+-----------+
| 2019-02-26T14:06:24.8055948 | KeePassTestSuite\AddNewEntry\Setup\StartAndLogin\StartSUT | proc-start       | C:\Users\user\Documents\Ranorex\RanorexStudio Projects\Samples\KeePassTestSuite\KeePassTestSuite\bin\Debug\KeePass\KeePass.exe | 37        |
+-----------------------------+-----------------------------------------------------------+------------------+-------------------------------------------------------------------------------------------------------------------------------+-----------+

PerfTracing_Input_<DateTimeStamp>.csv

Code: Select all

+-----------------------------+---------------------------------------------------------------------------+-------------------------------------------------+----------------------------------+----------+-----------+-------------+-----------------+-----------+
| TimeStamp                   | Module                                                                    | RepoItem                                        | RepoItemId                       | Device   | InputType | RepeatCount | NominalDuration | TotalTime |
+-----------------------------+---------------------------------------------------------------------------+-------------------------------------------------+----------------------------------+----------+-----------+-------------+-----------------+-----------+
| 2019-02-26T14:06:27.5520494 | KeePassTestSuite\AddNewEntry\Setup\StartAndLogin\Login                    | KeePassTestSuiteRepository.LogIn.MasterPassword | 982d26ce9282492b9795a6ecf745d931 | mouse    | click     | 1           | 100             | 201       |
+-----------------------------+---------------------------------------------------------------------------+-------------------------------------------------+----------------------------------+----------+-----------+-------------+-----------------+-----------+
| 2019-02-26T14:06:27.9490889 | KeePassTestSuite\AddNewEntry\Setup\StartAndLogin\Login                    | KeePassTestSuiteRepository.LogIn.MasterPassword | 982d26ce9282492b9795a6ecf745d931 | keyboard | sequence  | 1           | 100             | 314       |
+-----------------------------+---------------------------------------------------------------------------+-------------------------------------------------+----------------------------------+----------+-----------+-------------+-----------------+-----------+
| 2019-02-26T14:06:28.4436431 | KeePassTestSuite\AddNewEntry\Setup\StartAndLogin\Login                    | KeePassTestSuiteRepository.LogIn.BtOK           | 1c9d14c17d1345269e9bf5627600e539 | mouse    | click     | 1           | 100             | 177       |
+-----------------------------+---------------------------------------------------------------------------+-------------------------------------------------+----------------------------------+----------+-----------+-------------+-----------------+-----------+
| 2019-02-26T14:06:29.0576422 | KeePassTestSuite\AddNewEntry\AddEntryByRecording_DataIteration_1\AddEntry | KeePassTestSuiteRepository.MainForm.Edit        | 0467e35e9459401589a9cd4a06cb57c7 | mouse    | click     | 1           | 100             | 198       |
+-----------------------------+---------------------------------------------------------------------------+-------------------------------------------------+----------------------------------+----------+-----------+-------------+-----------------+-----------+

PerfTracing_Repo_<DateTimeStamp>.csv

Code: Select all

+-----------------------------+---------------------------------------------------------------------------+-------------------------------------------------+----------------------------------+----------------------------------------------------------------------------------------------------+------------------+---------------+----------------+-----------+-------+
| TimeStamp                   | Module                                                                    | RepoItem                                        | RepoItemId                       | RepoItemPath                                                                                       | EffectiveTimeout | TimesSearched | LastSearchTime | TotalTime | Found |
+-----------------------------+---------------------------------------------------------------------------+-------------------------------------------------+----------------------------------+----------------------------------------------------------------------------------------------------+------------------+---------------+----------------+-----------+-------+
| 2019-02-26T14:06:24.9123919 | KeePassTestSuite\AddNewEntry\Setup\StartAndLogin\Login                    | KeePassTestSuiteRepository.LogIn.MasterPassword | 982d26ce9282492b9795a6ecf745d931 | /form[@controlname='KeyPromptForm']/text[@controlname='m_tbPassword']/text[@accessiblerole='Text'] | 10000            | 6             | 1758           | 2593      | TRUE  |
+-----------------------------+---------------------------------------------------------------------------+-------------------------------------------------+----------------------------------+----------------------------------------------------------------------------------------------------+------------------+---------------+----------------+-----------+-------+
| 2019-02-26T14:06:27.7985673 | KeePassTestSuite\AddNewEntry\Setup\StartAndLogin\Login                    | KeePassTestSuiteRepository.LogIn.MasterPassword | 982d26ce9282492b9795a6ecf745d931 | /form[@controlname='KeyPromptForm']/text[@controlname='m_tbPassword']/text[@accessiblerole='Text'] | 10000            | 1             | 144            | 144       | TRUE  |
+-----------------------------+---------------------------------------------------------------------------+-------------------------------------------------+----------------------------------+----------------------------------------------------------------------------------------------------+------------------+---------------+----------------+-----------+-------+
| 2019-02-26T14:06:28.3186405 | KeePassTestSuite\AddNewEntry\Setup\StartAndLogin\Login                    | KeePassTestSuiteRepository.LogIn.BtOK           | 1c9d14c17d1345269e9bf5627600e539 | /form[@controlname='KeyPromptForm']/button[@controlname='m_btnOK']                                 | 10000            | 1             | 121            | 121       | TRUE  |
+-----------------------------+---------------------------------------------------------------------------+-------------------------------------------------+----------------------------------+----------------------------------------------------------------------------------------------------+------------------+---------------+----------------+-----------+-------+
| 2019-02-26T14:06:28.925642  | KeePassTestSuite\AddNewEntry\AddEntryByRecording_DataIteration_1\AddEntry | KeePassTestSuiteRepository.MainForm.Edit        | 0467e35e9459401589a9cd4a06cb57c7 | /form[@controlname='MainForm']/menubar[@controlname='m_menuMain']/menuitem[@accessiblename='Edit'] | 10000            | 1             | 126            | 126       | TRUE  |
+-----------------------------+---------------------------------------------------------------------------+-------------------------------------------------+----------------------------------+----------------------------------------------------------------------------------------------------+------------------+---------------+----------------+-----------+-------+

dhale
Posts: 21
Joined: Thu Feb 27, 2014 7:33 pm

Re: 9.0 Performance Tracing - Leverage the data

Post by dhale » Thu Feb 28, 2019 4:26 pm

Whats not clear to me is how best to use the data, because I don't fully understand the data itself.

For example, if I'm wanting to optimize my repo paths, what am I trying to minimize - the LastSearchTime, or TotalTime?
I don't quite understand TotalTime and how it is calculated - its not a multiple of anything that I can tell.
How can the total time exceed the Effective Timeout?

Below for example, are values from just one of my repo items after running several tests:
The repo item path for all of the data points below is simply:

Code: Select all

/form[@controlname='<<redacted>>']
So there isn't any optimization that really can be done, but just look at the data below- its all over the place:

Code: Select all

+-------------------------------------------------------------+
|EffectiveTimeout|TimesSearched|LastSearchTime|TotalTime|Found|
+-------------------------------------------------------------+
|3000            |79           |7             |19763    |TRUE |
+-------------------------------------------------------------+
|3000            |237          |529           |14822    |TRUE |
+-------------------------------------------------------------+
|3000            |196          |470           |12191    |TRUE |
+-------------------------------------------------------------+
|3000            |152          |387           |9614     |TRUE |
+-------------------------------------------------------------+
|3000            |55           |0             |3045     |FALSE|
+-------------------------------------------------------------+
|3000            |56           |0             |3038     |FALSE|
+-------------------------------------------------------------+
|3000            |55           |0             |3038     |FALSE|
+-------------------------------------------------------------+
|3000            |55           |0             |3024     |FALSE|
+-------------------------------------------------------------+
|3000            |46           |0             |3013     |FALSE|
+-------------------------------------------------------------+
|3000            |54           |0             |3013     |FALSE|
+-------------------------------------------------------------+
|3000            |54           |0             |2999     |FALSE|
+-------------------------------------------------------------+
|3000            |1            |96            |96       |TRUE |
+-------------------------------------------------------------+
|3000            |1            |57            |57       |TRUE |
+-------------------------------------------------------------+
|3000            |1            |54            |54       |TRUE |
+-------------------------------------------------------------+
|3000            |1            |37            |37       |TRUE |
+-------------------------------------------------------------+
|3000            |1            |22            |22       |TRUE |
+-------------------------------------------------------------+
|3000            |1            |21            |21       |TRUE |
+-------------------------------------------------------------+
|3000            |1            |20            |20       |TRUE |
+-------------------------------------------------------------+
|3000            |1            |14            |14       |TRUE |
+-------------------------------------------------------------+
|3000            |1            |10            |10       |TRUE |
+-------------------------------------------------------------+
|3000            |1            |8             |8        |TRUE |
+-------------------------------------------------------------+
|3000            |1            |8             |8        |TRUE |
+-------------------------------------------------------------+
|3000            |1            |7             |7        |TRUE |
+-------------------------------------------------------------+
|3000            |1            |6             |6        |TRUE |
+-------------------------------------------------------------+
|3000            |1            |6             |6        |TRUE |
+-------------------------------------------------------------+

User avatar
N612
Posts: 80
Joined: Mon Jul 11, 2016 4:01 pm

Re: 9.0 Performance Tracing - Leverage the data

Post by N612 » Thu Feb 28, 2019 6:36 pm

Hard to say why this item has inconsistent times without actually seeing the test solution and playback live (or a recording of it, also possible in Ranorex 9.0). I do not have any similar results in my test metrics to compare with. Perhaps the test waiting for the form to exist when the 'TimesSearched' were high and 'TotalTimes' were long? If so, this is more of a timing thing and not a performance issue.

Try filtering items with a 'TimesSearched' = 1 to eliminate timing anomalies in the data where it may have just been waiting for the element to exist. Then sort the 'TotalTime' from largest to smallest to see what elements are taking the longest.

dhale
Posts: 21
Joined: Thu Feb 27, 2014 7:33 pm

Re: 9.0 Performance Tracing - Leverage the data

Post by dhale » Thu Feb 28, 2019 8:19 pm

I think I'm going to reach out to support to see if they can get some usage clarification on this feature.
I'll ask if they can update the online documentation to assist others who may also have the same issues understanding this as I do.
A sample .xls as a download would have gone a long ways here for me in understanding how to use the available data to my advantage.

I would like to think that this is potentially a really useful feature - provided that there is a clear understanding on how best to use it.
We run thousands of tests, and shaving a few seconds off of areas where it isn't needed literally can equate to hours off of our run times.