Generating additional logs through IBM Rational Robot VU scripts

This article discusses how you can use IBM Rational Robot scripts to generate test logs outside the scope of IBM Rational TestManager. This allows you to analyze the logs even while the workload execution is still in progress.

Share:

Manish Aneja (mananeja@in.ibm.com), System Software Engineer, India Software Labs, IBM

Manish Aneja is working as a system software engineer on the System Verification Test Reliability team for IBM Workplace Collaborative Services in the IBM India Software Labs, Gurgaon. His primary expertise is in system tests, and he has developed automation for reliability test and problem determination. He holds a Masters degree in computer applications.



06 February 2007

Testing during workload execution

In reliability and performance testing, you use IBM® Rational® TestManager to test a product during workload executions. Based on the test scenarios and targets, the workloads can have a duration from a few hours to several days. During long duration workload executions (for example, five-day runs), logs provided by Rational TestManager are available for analysis only after the completion of the workload. Moreover, these log files grow to an unmanageable size, and hence are kept disabled for most of the cases.

As a result, you are unable to start analyzing client logs until the execution completes. This makes it difficult to analyze user activity, root causes of failures, and the end user interactions that hamper problem determination.

This article discusses a technique that you can implement using IBM® Rational® Robot scripts to generate additional logs outside the scope of Rational TestManager. These logs can be analyzed even while the workload execution is in progress.


Workload setup

Workload is the mode to generate load on a system under test (SUT) using different scenarios. Rational TestManager and Rational Robot are the tools that can be used to execute the workload. Rational TestManager provides the environment to execute the workload, and Rational Robot generates VU (Virtual User) scripts with emulation commands that will be executed during the workload run.

Executing these tests creates a set of various log files. Some of them are generated at client side (that is, through IBM Rational TestManager) and others are generated at SUT. These logs are parsed, filtered, and analyzed to uncover issues encountered during test activity. The task of mapping and analyzing these logs is usually called Problem Determination.

The usual setup for workload execution is shown in Figure 1.

Figure 1. Workload execution setup
diagram showing system under test

During long duration workload executions, you have the following concerns to address:

  • Logs provided by Rational TestManager are available for analysis only after the completion of workload.
  • Rational TestManager log files can grow to unmanageable size as workload executes for many days, and are therefore kept disabled for most of the cases.
  • Log files often get corrupted during transfer from the test agents to the test manager.

Following are techniques to help you record logs that you can analyze during runtime.


Recording user activities at the run time

In this technique you will generate an HTTP request to capture VU activity at a particular point in time. The access logs for this HTTP request can be analyzed even while the execution is in progress, because these log files will be independent from the Rational TestManager. To implement this technique follow these steps.

  1. Identify the key elements to capture the state and actions of the user.

    These elements will enable you to identify the action performed by the VU at a particular point in time. A few of the elements you might identify include:

    • Hostname: the system from which the request is executed
    • User name: the name of the user performing the task
    • Operation name: the name of the user group or task to be performed
    • Script name: the current script that the VU is executing
    • Start time of operation
    • End time of operation
    • Current Iteration: as the same task is performed multiple times, it can denote which iteration is being performed.

    This list can be customized based on your test scenarios and requirements.

  2. Generate an HTTP request with all of these elements added to the request in parameter-value form in VU scripts.

    The supplementary logic for this HTTP request (along with additional variables) needs to be implemented in VU scripts by adding the code shown in Listing 1 to simulate an additional HTTP request.

    Listing 1. Sample HTTP request
    "GET /additionalLog/Log.html?Hostname="+_host+"&User_Group="+_user_group+"
    &Script="+_script+"&Current_Iteration="+itoa(Iteration_No)+"
    &User_Name="+User+"&Transaction_Start_Time="+tod()+" HTTP/1.1\r\n"

    The initial path in this HTTP request (/additionalLog/Log.html) indicates an HTML file (Log.html) placed in the directory additionalLog at the root of the Web server, which in turn is located at the default root of the Web server. The default location of the root is ..\htdocs, but can be confirmed from information in the httpd.conf file of the Web server.

    The desired parameters are appended to this HTML request after the question mark symbol (?). The names and values of these parameters is separated by the equal sign (=). The value for these parameters needs to be converted to string data type before you can use the corresponding user-defined and script variables in the request.

    In the request detailed in Listing 1, _host is a script variable that provides the value for Hostname. Iteration_No is a user-defined numeric variable that provides a count of the iterations performed until the time information is captured. This information is converted to a string using the itoa function.

  3. Determine where to place these additional HTTP requests in VU scripts.

    Generally, all VU scripts a have number of HTTP requests embedded in them, even if they are recorded for single-user action. However, there will be one or two primary requests of interest that indicate the user operation. Other requests are usually for supporting images and files for that request.

    There will be two additional requests for each primary user operation in each VU script:

    • One just before the operation is performed, to capture the start time of the operation
    • One just after the operation, to capture the finish time of the operation

    In other words, the primary operation request in the VU script will be surrounded by two additional log requests. The one before it will have the start time parameter of the operation, and the one after it will have the finish time parameter of the operation.

    For the end time HTTP request, you can change the parameter name Transaction_Start_Time to Transaction_Finish_Time and the rest of the requests will remain the same, because you are using the built-in tod function to capture the value of the end time at runtime.

  4. Set up an additional Web server.

    You have to set up a Web server to execute these additional HTTP requests. Once executed, the request will be stored in the Web server’s access logs, which can be analyzed to gather the details required.

    It is recommended that you introduce a separate Web server to execute these requests, to ensure that you are not disturbing the SUT. Generating the HTTP request requires minimal effort on the part of the VU, because most of the desired values will be available. You just have to assemble them in the HTTP request.

    In order to set up the additional Web server, you need to install any Web server available for use, and then create the hierarchy in the root of the Web server based on the path you have used in the HTTP request. In this case, you have to create a folder called additionalLog at the root of the Web server, and then place the Log.html file in that folder.

    Once the setup is done, it should allow you to open the following URL: http://Webserver_name/folder_hierarchy/Log.html

    You can customize the HTTP request generated previously, and replace the HTML file with any resource placed on a path that is accessible through the Web server.

    The test environment will look like that shown in Figure 2.

    Figure 2. Test environment showing the separate Web server
    same diagram as figure 1 but with another server
  5. Collect access logs from the Web server

    After the VU scripts have executed, you can collect the user activity details from the additional Web server’s access log, which stores all of the HTTP requests catered by the Web server. Therefore, you need to grab this log file to get the user activity details. The default location for this file is in the logs folder in the installation path of the Web server.


How to use these logs

The logs are generated in uniform format, and you need to parse them to obtain additional information (such as server response time and transaction count at any point of time during the workload).

The sample log entry will look like that shown in Listing 2.

Listing 2. Access log entry
x.x.x.x - - [21/Jul/2006:10:30:01 +0100] 
"GET /additionalLog/Log.html?Hostname=Agent1&User_Group=Operation1&Script=Test_Script
&Current_Iteration=1&CBE&User_Name=TestUser101
&Transaction_Start_Time=Fri%20Jul%2021%2010:30:01%202006 HTTP/1.1" 200 54

Log data

The information in the log is presented as follows:

  • x.x.x.x is the IP address of the test machine from which the HTTP request was generated.
  • Hostname=Agent1 is the name of the test machine.
  • User_Group=Operation1 is the user group to which the virtual user belongs.
  • Script=Test_Script is the name of current script the user is executing.
  • Current_Iteration=1 is the current value of the iteration in progress.
  • User_ID=TestUser101 is the user name.
  • Transaction_Start_Time=Fri%20Jul%2021%2010:30:01%202006 is the start time of the transaction. Replace "%20" with a space character to get a meaningful format.

Analyzing the data

Now you can look at the data to understand the information that you captured:

  • To get the response time of the server at any instance of time, you need to subtract the start time from the end time entries of any operation. The result is the response time for the server for that operation at that instance.
  • Because you have one start time entry for each prime operation that is performed, you can calculate the number of log entries for a certain duration, and use that to get the transaction rate at that instance of time.
  • If a VU exits before its scheduled completion (in other words, abnormal termination), you can filter the log entries for that particular user. Then analyze the filtered entries to learn about the script the user was executing and check if the SUT logs show any exception at that instance.
  • If exceptions or errors appear in SUT logs, you can map them to user activities based on the timestamp of the logs.

Benefits

Implementing the technique explained above will result in the following advantages:

  • You can start user activity analysis as soon as the workload execution starts.
  • User activity logs enable failure analysis, even when client logging is disabled.
  • You can analyze the system load for transaction rate, count, and response time by customizing user activity logs.
  • You can map SUT exceptions to end user activities in real time.

Conclusion

These additional logs can help you understand the cause of failures and validate data when Rational TestManager logging for workload is not enabled, which is normally the case with long duration workloads. In addition, you can access these log files for analysis while the workload is in progress, without waiting for it to be completed.

Resources

Learn

Discuss

Comments

developerWorks: Sign in

Required fields are indicated with an asterisk (*).


Need an IBM ID?
Forgot your IBM ID?


Forgot your password?
Change your password

By clicking Submit, you agree to the developerWorks terms of use.

 


The first time you sign into developerWorks, a profile is created for you. Information in your profile (your name, country/region, and company name) is displayed to the public and will accompany any content you post, unless you opt to hide your company name. You may update your IBM account at any time.

All information submitted is secure.

Choose your display name



The first time you sign in to developerWorks, a profile is created for you, so you need to choose a display name. Your display name accompanies the content you post on developerWorks.

Please choose a display name between 3-31 characters. Your display name must be unique in the developerWorks community and should not be your email address for privacy reasons.

Required fields are indicated with an asterisk (*).

(Must be between 3 – 31 characters.)

By clicking Submit, you agree to the developerWorks terms of use.

 


All information submitted is secure.

Dig deeper into Rational software on developerWorks


static.content.url=http://www.ibm.com/developerworks/js/artrating/
SITE_ID=1
Zone=Rational
ArticleID=193202
ArticleTitle=Generating additional logs through IBM Rational Robot VU scripts
publish-date=02062007