sub-second

Load Testing with Selenium Grid

2015-09-29T15:33:00.003-07:00

Selenium grid is an open source browser-based test tool that allows multiple concurrent browsers to run at the same time, spread across a number of nodes. With each node running multiple browsers and many nodes in place, a significant number of concurrent browsers be pointed at a web site and substantial load generated.

Some Advantages

Selenium webdriver runs real browsers which execute javascript on the client-side and can give realistic response times and realistic user behavior.

Selenium integrates well with modern java stacks such as junit, testng, jenkins, gradle, ant, etc.

Cost.

Some Drawbacks

There may be bugs, such as limited compatibility with some versions of some browsers.

There may be maintenance overhead.

The amount of load that can be generated is limited. Real browsers are expensive to run in terms of cpu and memory requirements, so a lot of client nodes can be required to generate enough load. It is more appropriate for moderate load. I'm not sure what the limits of the number of concurrent browsers this approach will support, but dozens of concurrent browsers can easily be supported. It is possible that hundreds of concurrent browsers may be too much. For very large tests, commercial tools and more efficient load generation approaches targeting lower-level traffic may be more suitable.

How

Set up a selenium grid hub and a number of selenium grid nodes registered to that hub. This can be done in a cloud provider such as AWS or using on-premise hardware.
The desired versions of browsers to be tested should be installed on the nodes.
Nodes should have graphics cards that give responsive browser behavior.
Limit the max number of browsers per node to be no more than the number of CPUs per node.
Other than for node debugging, disable node logging which can be very verbose and fill up the file system.
In the java client test application, each test thread should get a thread local instance of Selenium WebDriver. This will result in a thread-safe WebDriver, with browsers not interfering with one another.
Test the node infrastructure by, for example, running five browsers on one node versus running one browser on each of five nodes.
Once the grid infrastructure has been validated, the target website can then be tested for scalability by slowly ramping up the number of concurrent browsers until response time knee is hit.
Stability of the target website can be tested by running near peak load for an extended period of time. Be sure to log results along the way in case of a client-side crash.
Browser snapshots can be saved when errors are encountered, making bug identification simple.

Performance Testing in a Continuous Integration Environment

2013-12-03T15:16:00.002-08:00

Software development groups with continuous integration in place (to handle automatic build and test on any check-in) should ideally include performance and load testing in the continuous integration process. This article describes my experiences implementing such a solution at a large enterprise software company.

Infrastructure Needed

A continuous integration system such as jenkins, teamcity, etc. that is able to build code and run tests
An automated deployment system that can programmatically deploy and start newly built code
A performance test framework supporting performance tests that are runnable by the continuous integration system against the automatically deployed code

Performance test framework
The performance test framework could be a third-party framework such as jmeter that integrates well with CI systems, unit test frameworks (such as testng or junit) and other open source software. the solution I chose was to implement an in-house performance test framework. This perf test framework was designed to make it trivial to take an arbitrary junit test class and convert it to a performance test with less than 5 minutes of work. This allows the extensive library of automated tests already implemented (in the junit framework) to be leveraged as performance test cases.

This performance test framework supported functionality including the following, which would be a reasonable minimal set of performance test framework functionality:

Allow any test case to be converted to a performance test with minimal effort. (In this case, it is achieved by having the test class extend a PerfTestBase class and implement an IPerfTest interface.)
Allow any block of code to be wrapped as a transaction to be measured.
Allow the test to be run for a configured amount of time or a configured number of iterations.
Allow the test to be run concurrently by a configurable number of client threads.
Allow the test to gradually scale up load as configured, such as 1 test case at a time, 2 concurrent test cases, 5 concurrent test cases, etc.
Handle exceptions and errors.
Allow the test to pass or fail based on configurable performance criteria such as response time SLAs, performance versus previous test runs, etc.
Allow the test to be run in an IDE, from the command line, and from the continuous integration system.
Persist results in a database for historical reporting
Automatically generate test result artifacts and charts including response time trends over time, performance relative to previous test runs, performance versus number of concurrent test cases, etc.
Automatically calculate any performance metrics needed for reporting.
Automatically push results to sinks such as email distribution lists, dashboards, third party reporting repositories, etc.

Stretch goals for a performance test framework include the following:

Handle stress test cases in which the test process, the services under test, or the OS might freeze up, requiring external monitoring and catastrophic failure handling.
Handle capacity testing in which the absolute capacity of a service is reached programmatically.
Handle performance of fault-tolerance scenarios in which some of the services under test are programmatically brought down and up.

Findings
My experience doing performance testing within the continuous integration system is that the tests find, on a daily basis, deep stability and performance bugs. Bugs found include deadlocks, race conditions, out of memory exceptions, process crashes, response time regressions, etc. This allows a very large amount of performance testing to be done with minimal staffing resources. There are up-front costs implementing the tests and getting them running the continuous integration system. Once the performance tests are implemented, the bulk of the ongoing work involves triaging, driving and resolving the performance and stability bugs that are found automatically on a daily basis.

I believe this type of system constitutes a significant leap forward versus traditional manual performance testing. Traditional, manual performance testing is labor intensive and requires expensive, antiquated third-party testing tools.

Timing Command Line Applications on Linux

2013-02-05T09:55:00.007-08:00

The command line time utility available on linux as /usr/bin/time can be used to measure the elapsed time of test applications launched from the command line, and also measure other information such as cpu time and other metrics, outputting the result as a csv file that can then be easily charted. Using the "format" option of the time utility allows the output to be formatted as csv with a single line per app run, rather than the default output which contains multiple lines of output.

Script

echo TestCase , Seconds , RealTime , CpuTimeUser , CpuTimeKernel
/usr/bin/time --format="MyTestCase1 , %e , %E , %U , %S" ./mytestcase1.sh mytestcase1parameter

/usr/bin/time --format="MyTestCase2 , %e , %E , %U , %S" java -jar mytestcase2.jar

Output

TestCase , Seconds , RealTime , CpuTimeUser , CpuTimeKernel

MytestCase1 , 679.33 , 11:19.33 , 227.13 , 105.85

MytestCase2 , 460.99 , 7:40.99 , 96.32 , 44.64

Format String

The format string can be configured to output the following options:

Time

%E Elapsed real time (in [hours:]minutes:seconds).

%e (Not in tcsh.) Elapsed real time (in seconds).

%S Total number of CPU-seconds that the process spent in kernel mode.

%U Total number of CPU-seconds that the process spent in user mode.

%P Percentage of the CPU that this job got, computed as (%U + %S) / %E.

Memory

%M Maximum resident set size of the process during its lifetime, in Kbytes.

%t (Not in tcsh.) Average resident set size of the process, in Kbytes.

%K Average total (data+stack+text) memory use of the process, in Kbytes.

%D Average size of the processâs unshared data area, in Kbytes.

%p (Not in tcsh.) Average size of the processâs unshared stack space, in Kbytes.

%X Average size of the processâs shared text space, in Kbytes.

%Z (Not in tcsh.) Systemâs page size, in bytes. This is a per-system constant, but varies between systems.

%F Number of major page faults that occurred while the process was running. These are faults where the page has to be read in from

disk.

%R Number of minor, or recoverable, page faults. These are faults for pages that are not valid but which have not yet been claimed by

other virtual pages. Thus the data in the page is still valid but the system tables must be updated.

%W Number of times the process was swapped out of main memory.

%c Number of times the process was context-switched involuntarily (because the time slice expired).

%w Number of waits: times that the program was context-switched voluntarily, for instance while waiting for an I/O operation to com-

plete.

I/O

%I Number of file system inputs by the process.

%O Number of file system outputs by the process.

%r Number of socket messages received by the process.

%s Number of socket messages sent by the process.

%k Number of signals delivered to the process.

%C (Not in tcsh.) Name and command-line arguments of the command being timed.

%x (Not in tcsh.) Exit status of the command.

Loadrunner How to Download an Image

2012-12-10T10:16:00.000-08:00

Usually images such as jpg, gif, png, etc., will be downloaded automatically as extra resources. However, occasionally it is necessary to download images directly. Downloading an image directly can be done easily as follows:

make web_url call requesting jpg, gif, png, etc.
Set Resource=1 indicating the the downloaded item is a resource
Use content type/mime type "image/jpg", "image/gif", "image/png", etc.

The following script illustrates this method as follows:

Image of type png is downloaded
Downloaded image file size is retrieved and checked that it is as expected.
Script writes an error message is the downloaded size is not as expected.

Script

Action()
{
long imgSize=0;

web_url("test pdf download",
"URL=http://www.google.com/images/nav_logo114.png",
"Resource=1",
"RecContentType=image/png",
"Snapshot=t1.inf",
LAST);

// Save pdf file size
imgSize = web_get_int_property(HTTP_INFO_DOWNLOAD_SIZE);

// Verify size is as expected (~28765 bytes 321 header bytes)
if (imgSize < 28765 ) {
lr_error_message("File download error, expected ~247,800 bytes but got %d", imgSize);
} else {
lr_output_message("File downloaded size okay, expected ~247,800 bytes and got %d", imgSize);
}

return 0;
}

Console Output

Running Vuser...
Starting iteration 1.
Starting action Action.
Action.c(6): web_url("test pdf download") was successful, 28765 body bytes, 321 header bytes [MsgId: MMSG-26386]
Action.c(14): web_get_int_property was successful [MsgId: MMSG-26392]
Action.c(20): File downloaded size okay, expected ~247,800 bytes and got 29086
Ending action Action.
Ending iteration 1.
Ending Vuser...

Loadrunner How to Download PDF File

2012-12-07T09:58:00.004-08:00

A pdf file can be downloaded in loadrunner as follows:

make web_url call requesting pdf
Set Resource=1 indicating the the downloaded item is a resource
Use content type/mime type "application/pdf"

The following script illustrates this method as follows:

Pdf is downloaded
Downloaded pdf file size is retrieved and checked that it is as expected.
Pdf file contents is saved to a parameter

Script

Action()

{

long pdfSize=0;

web_reg_save_param("pdfContent",

"LB=",

"RB=",

LAST );

web_url("test pdf download",

"URL=http://research.google.com/archive/disk_failures.pdf",

"Resource=1",

"RecContentType=application/pdf",

"Snapshot=t1.inf",

LAST);

// Save pdf file size

pdfSize = web_get_int_property(HTTP_INFO_DOWNLOAD_SIZE);

// Verify size is as expected (~247808 bytes)

if (pdfSize < 247000) {

//End the transaction

lr_error_message("File download error, expected ~247,800 bytes but got %d", pdfSize);

} else {

lr_output_message("File downloaded size okay, expected ~247,800 bytes and got %d", pdfSize);

}

lr_output_message("pdfContent=%s", lr_eval_string("{pdfContent}"));

return 0;

}

Console Output

Starting action Action.

Action.c(6): Registering web_reg_save_param was successful [MsgId: MMSG-26390]

Action.c(11): Redirecting "http://research.google.com/archive/disk_failures.pdf" (redirection depth is 0) [MsgId: MMSG-26694]

Action.c(11): To location "http://static.googleusercontent.com/external_content/untrusted_dlcp/research.google.com/en/us/archive/disk_failures.pdf" [MsgId: MMSG-26693]

Action.c(11): web_url("test pdf download") was successful, 247808 body bytes, 715 header bytes [MsgId: MMSG-26386]

Action.c(19): web_get_int_property was successful [MsgId: MMSG-26392]

Action.c(26): File downloaded size okay, expected ~247,800 bytes and got 248523

Action.c(30): pdfContent=HTTP/1.0 302 Found

Location: http://static.googleusercontent.com/external_content/untrusted_dlcp/research.google.com/en/us/archive/disk_failures.pdf

Cache-Control: private

Content-Type: text/html; charset=UTF-8

Mysql Performance Monitoring - Script

2012-11-21T10:46:00.003-08:00

The following provides a linux shell script that provides some basic mysql performance monitoring. It reports the following metrics every N seconds based on the parameter passed in:

timestamp
queries per second
threads connected
connections
slow queries per second
rows read per second
rows inserted per second
rows updated per second
rows deleted per second

The results are written into a csv output file mysql-stats.csv.

Script

# mysql-stats.sh
# mysql stats sampled every $1 seconds until stopped
#

if [ "$1" == "" ] ; then
echo "syntax= ./mysql-stats.sh <intervalSeconds>"
exit
fi

time=$1
origqps=`mysql -u username -p password "show status" | awk '{if ($1 == "Queries") print $2}'`
origconn=`mysql -u username -p password "show status" | awk '{if ($1 == "Threads_connected") print $2}'`
origconnattempt=`mysql -u username -p password "show status" | awk '{if ($1 == "Connections") print $2}'`
origslowqry=`mysql -u username -p password "show status" | awk '{if ($1 == "Slow_queries") print $2}'`
origrowsread=`mysql -u username -p password "show status" | awk '{if ($1 == "Innodb_rows_read") print $2}'`
originserted=`mysql -u username -p password "show status" | awk '{if ($1 == "Innodb_rows_inserted") print $2}'`
origupdated=`mysql -u username -p password "show status" | awk '{if ($1 == "Innodb_rows_updated") print $2}'`
origdeleted=`mysql -u username -p password "show status" | awk '{if ($1 == "Innodb_rows_deleted") print $2}'`

echo "Stats (show status) sampled every $time seconds" > mysql-stats.csv
echo "Time , Queries , Threads_connected , Connections , Slow_queries , Innodb_rows_read , inserted , updated , deleted" >> mysql-stats.csv

x=1
while :
do

sleep $time
lastqps=`mysql -u username -p password "show status" | awk '{if ($1 == "Queries") print $2}'`
lastconn=`mysql -u username -p password "show status" | awk '{if ($1 == "Threads_connected") print $2}'`
lastconnattempt=`mysql -u username -p password "show status" | awk '{if ($1 == "Connections") print $2}'`
lastslowqry=`mysql -u username -p password "show status" | awk '{if ($1 == "Slow_queries") print $2}'`
lastrowsread=`mysql -u username -p password "show status" | awk '{if ($1 == "Innodb_rows_read") print $2}'`
lastinserted=`mysql -u username -p password "show status" | awk '{if ($1 == "Innodb_rows_inserted") print $2}'`
lastupdated=`mysql -u username -p password "show status" | awk '{if ($1 == "Innodb_rows_updated") print $2}'`
lastdeleted=`mysql -u username -p password "show status" | awk '{if ($1 == "Innodb_rows_deleted") print $2}'`

diffqps=`expr $lastqps - $origqps`
#diffconn=`expr $lastconn - $origconn`
diffconnattempt=`expr $lastconnattempt - $origconnattempt`
diffslowqry=`expr $lastslowqry - $origslowqry`
diffrowsread=`expr $lastrowsread - $origrowsread`
diffinserted=`expr $lastinserted - $originserted`
diffupdated=`expr $lastupdated - $origupdated`
diffdeleted=`expr $lastdeleted - $origdeleted`

avgqps=`expr $diffqps / $time`
#avgconn=`expr $diffconn / $time`
avgconnattempt=`expr $diffconnattempt / $time`
avgslowqry=`expr $diffslowqry / $time`
avgrowsread=`expr $diffrowsread / $time`
avginserted=`expr $diffinserted / $time`
avgupdated=`expr $diffupdated / $time`
avgdeleted=`expr $diffdeleted / $time`

#echo "$avgqps"
date=`date`
echo "$date , $avgqps , $lastconn , $avgconnattempt , $avgslowqry , $avgrowsread , $avginserted , $avgupdated , $avgdeleted" >> mysql-stats.csv

origqps=$lastqps
origconn=$lastconn
origconnattempt=$lastconnattempt
origslowqry=$lastslowqry
origrowsread=$lastrowsread
originserted=$lastinserted
origupdated=$lastupdated
origdeleted=$lastdeleted

done

Output

Stats (show status) sampled every 10 seconds
Time , Queries , Threads_connected , Connections , Slow_queries , Innodb_rows_read , inserted , updated , deleted
Tue Sep 18 14:32:37 PDT 2012 , 13 , 5 , 0 , 0 , 45 , 0 , 0 , 0
Tue Sep 18 14:32:47 PDT 2012 , 13 , 5 , 0 , 0 , 45 , 0 , 0 , 0
Tue Sep 18 14:32:57 PDT 2012 , 1374 , 5 , 0 , 0 , 258 , 352 , 0 , 153
Tue Sep 18 14:33:07 PDT 2012 , 4061 , 26 , 2 , 0 , 907 , 976 , 28 , 83
Tue Sep 18 14:33:17 PDT 2012 , 12122 , 26 , 0 , 0 , 374 , 3026 , 0 , 89
Tue Sep 18 14:33:27 PDT 2012 , 9714 , 26 , 0 , 0 , 45 , 2412 , 0 , 0
Tue Sep 18 14:33:37 PDT 2012 , 8694 , 26 , 0 , 0 , 45 , 2162 , 0 , 0
Tue Sep 18 14:33:47 PDT 2012 , 4659 , 26 , 0 , 0 , 45 , 1153 , 0 , 0
Tue Sep 18 14:33:57 PDT 2012 , 4237 , 26 , 0 , 0 , 45 , 1053 , 0 , 0
Tue Sep 18 14:34:07 PDT 2012 , 3668 , 26 , 0 , 0 , 332 , 921 , 0 , 108
Tue Sep 18 14:34:17 PDT 2012 , 3739 , 26 , 0 , 0 , 45 , 928 , 0 , 0
Tue Sep 18 14:34:27 PDT 2012 , 3636 , 26 , 0 , 0 , 45 , 902 , 0 , 0
Tue Sep 18 14:34:38 PDT 2012 , 4526 , 26 , 0 , 0 , 45 , 1125 , 0 , 0
Tue Sep 18 14:34:48 PDT 2012 , 3734 , 26 , 0 , 0 , 45 , 927 , 0 , 0
Tue Sep 18 14:34:58 PDT 2012 , 3678 , 26 , 0 , 0 , 45 , 912 , 0 , 0

Mysql Performance Monitoring - Graphical Tool

2012-11-19T16:41:00.000-08:00

One simple method of mysql performance monitoring is using the free tool MysqlMonitorTool. It allows you to connect to a set of mysql instances and view charts showing some basic performance information including the following:

connections
inserted rows per second
updated rows per second
deleted rows per second
read rows per second
slow queries per second
queries per second

The following shows the display:

The tool is fairly easy to use as follows:

Download and unzip from http://sourceforge.net/projects/mysqlmt/
Create a batch or executable script that points to the tool's jar file: java -jar MysqlMonitorTool.jar
Run the batch script
Click server configuration, then click "add new server", then enter your server configuration (servername, host, port, username, password) for one or more mysql instances.
Click "add new server group" and create a server group and add the servers you created to the group.
Connect and the app will connect to your instances and provide the following tabs:

ProcessList
charts
Status Vars
Server Vars
Recording (to record chart output)

Loadrunner Check for Substring in Response

2012-11-19T13:46:00.002-08:00

The following describes one method for checking a response for a specific substring. The method is:

Use web_reg_find to search the response to the next request for the specified substring, saving the count in a parameter
Make the request
Check the count parameter for the number of occurrences of the substring

The following script illustrates the method, searching for the substrings "Google" and "Microsoft" in an http request to http://www.google.com, printing out the results.

Script

Action()
{
char *response;

// save response
web_reg_save_param("responseParam",
"LB=",
"RB=",
LAST );

// check response for substrings "Google" and "Microsoft"
web_reg_find("Text=Microsoft", "SaveCount=microsoft_count", LAST );
web_reg_find("Text=Google", "SaveCount=google_count", LAST );

// send request
web_url("test",
"URL=http://www.google.com",
"Resource=1",
"RecContentType=text/plain",
"Referer=http://www.google.com/",
"Snapshot=t12.inf",
LAST);

// Save respone to string
//response = lr_eval_string(lr_eval_string("{responseParam}"));
//lr_message("response = %s", response);

// check whether substring "Google" was found
if (strcmp(lr_eval_string("{google_count}"), "0") > 0) {
lr_output_message("Found %s occurrences of substring \"Google\" in response", lr_eval_string("{google_count}"));
} else {
lr_output_message("Did not find substring \"Google\" in response");
}

// check whether substring "Microsoft" was found
if (strcmp(lr_eval_string("{microsoft_count}"), "0") > 0) {
lr_output_message("Found %s occurrences of \"Microsoft\" in response", lr_eval_string("{search_count}"));
} else {
lr_output_message("Did not find substring \"Microsoft\" in response");
}

return 0;
}

Console Output

Starting iteration 1.
Starting action Action.
Action.c(7): Registering web_reg_save_param was successful [MsgId: MMSG-26390]
Action.c(13): Registering web_reg_find was successful [MsgId: MMSG-26390]
Action.c(14): Registering web_reg_find was successful [MsgId: MMSG-26390]
Action.c(17): Registered web_reg_find successful for "Text=Microsoft" [MsgId: MMSG-26362]
Action.c(17): Registered web_reg_find successful for "Text=Google" (count=7) [MsgId: MMSG-26364]
Action.c(17): web_url("test") was successful, 5034 body bytes, 736 header bytes [MsgId: MMSG-26386]
Action.c(31): Found 7 occurrences of substring "Google" in response
Action.c(40): Did not find substring "Microsoft" in response
Ending action Action.
Ending iteration 1.

Loadrunner Logging Options

2012-11-07T12:21:00.003-08:00

There are a number of different functions provided by Loadrunner for logging, including:

lr_message
lr_output_message
lr_error_message
lr_log_message
lr_debug_message
lr_vuser_status_message

This post provides a script illustrating each of these logging methods, and a description of the differences.

lr_message
The limitation of lr_message is that no source file (such as Action.c) or line number is provided.

lr_output_message

lr_output_message includes source file and line number information which is useful for debugging issues.

lr_error_message

lr_error_message flags the message as an error rather than informational.

lr_log_message

lr_log_message can reduce some network traffic during load tests by not sending messages to the load test output window.

lr_debug_message

lr_debug_message can write message conditionally on certain logging settings being enabled

lr_vuser_status_message

lr_vuser_status_message updates the vuser status field during load tests

The following script illustrates the various logging methods.

Script

Action()
{
// setup test message data
int msgLevel;
char *message = "This is a test message.";
// save string to a parameter
lr_save_string(message, "messageParam");

// lr_message test
lr_message("---------------------- lr_message --------------------------");
lr_message("--- lr_message does not show the source file and line number");
lr_message("--- lr_message: %s", message);
lr_message("----------------- end lr_message ---------------------");

// lr_output_message test
lr_message("------------------- lr_output_message -----------------------");
lr_message("--- lr_output_message does show the source file and line number");
lr_output_message("--- lr_output_message: %s", message);
lr_message("----------------- end lr_output_message ---------------------");

// lr_error_message test
lr_message("------------------- lr_error_message -----------------------");
lr_message("--- lr_error_message writes a message with an Error log level");
lr_error_message("--- lr_error_message: %s", message);
lr_message("----------------- end lr_error_message ---------------------");

// lr_log_message test
lr_message("------------------- lr_log_message ------------------------");
lr_message("--- lr_log_message does not send messages to the output window and could therefore reduce network traffic between agent and load generator in some situations");
lr_log_message("--- lr_log_message: %s", message);
lr_message("----------------- end lr_log_message ---------------------");

// lr_debug_message test
lr_message("------------------- lr_debug_message -----------------------");
lr_message("--- lr_debug_message writes a message if the specified log settings are set");
msgLevel=lr_get_debug_message();
if (msgLevel & LR_MSG_CLASS_BRIEF_LOG ) {
lr_message("standard log is enabled");
} else if (msgLevel & LR_MSG_CLASS_EXTENDED_LOG ) {
lr_message("extended log is enabled");
} else if (msgLevel & LR_MSG_CLASS_DISABLE_LOG ) {
lr_message("log is disabled");
}

// log message if brief or extended log are enabled
lr_debug_message(LR_MSG_CLASS_BRIEF_LOG | LR_MSG_CLASS_EXTENDED_LOG, "--- lr_debug_message: %s", "This is written if brief or extended log is enabled");

// disable brief and extended log
lr_set_debug_message(LR_MSG_CLASS_BRIEF_LOG, LR_SWITCH_OFF);
lr_set_debug_message(LR_MSG_CLASS_EXTENDED_LOG, LR_SWITCH_OFF);

// now the debug message should not be written
lr_debug_message(LR_MSG_CLASS_BRIEF_LOG | LR_MSG_CLASS_EXTENDED_LOG, "This should not be written to log because brief and extended log are both disabled");

// re-enable extended log
lr_set_debug_message(LR_MSG_CLASS_EXTENDED_LOG, LR_SWITCH_ON);

lr_message("----------------- end lr_debug_message ---------------------");

// lr_vuser_status_message
// lr_log_message test
lr_message("------------------- lr_vuser_status_message ------------------------");
lr_message("--- lr_vuser_status_message updates the status field of the vuser status area. It does not write to the log");
lr_vuser_status_message("--- lr_vuser_status_message: %s", message);
lr_message("----------------- end lr_vuser_status_message ---------------------");

return 0;
}

Output

Running Vuser...

Starting iteration 1.

Starting action Action.

---------------------- lr_message --------------------------

--- lr_message does not show the source file and line number

--- lr_message: This is a test message.

----------------- end lr_message ---------------------

------------------- lr_output_message -----------------------

--- lr_output_message does show the source file and line number

Action.c(19): --- lr_output_message: This is a test message.

----------------- end lr_output_message ---------------------

------------------- lr_error_message -----------------------

--- lr_error_message writes a message with an Error log level

Action.c(25): Error: --- lr_error_message: This is a test message.

----------------- end lr_error_message ---------------------

------------------- lr_log_message ------------------------

--- lr_log_message does not send messages to the output window and could therefore reduce network traffic between agent and load generator in some situations

--- lr_log_message: This is a test message.

----------------- end lr_log_message ---------------------

------------------- lr_debug_message -----------------------

--- lr_debug_message writes a message if the specified log settings are set

extended log is enabled

--- lr_debug_message: This is written if brief or extended log is enabled

----------------- end lr_debug_message ---------------------

------------------- lr_vuser_status_message ------------------------

--- lr_vuser_status_message updates the status field of the vuser status area. It does not write to the log

----------------- end lr_vuser_status_message ---------------------

Ending action Action.

Ending iteration 1.

Ending Vuser...

Starting action vuser_end.

Ending action vuser_end.

Vuser Terminated.

Loadrunner Asynchronous Results Polling Using 11.5 Web Async

2012-11-01T14:49:00.001-07:00

Some user action trigger asynchronous server-side operations. The user can then be forced to check for results periodically by polling the server. Loadrunner 11.5 provides asynchronous logic allowing callback functions to be specified which are called when the async call finally returns. The following example gives one example of using the asynchronous callbacks as follows:

Include web_api.h to load some needed symbols
To capture the time it takes for the async response to come back, specify a global variable showing done state
Before the async call, set async polling properties using web_reg_async_attributes such as how often to poll, which callback functions to use, etc.
Define the callback functions to be called when the async response is returned and update the done state variable in the callback
Make the async call
To get the response time, wait until the callback has updated the global state variable
End the transaction
Stop the async polling

The following shows an example of a script doing this, and the next section shows the script's vugen console output.

Script

// Specify include files
#ifndef _GLOBALS_H
#define _GLOBALS_H

#include "web_api.h"
#endif // _GLOBALS_H
// End include files

// Define a global variable holding done state
int done;

Action()
{
    web_url("wiki",
        "URL=http://ajaxify.com/run/wiki",
        "Resource=0",
        "RecContentType=text/html",
        "Referer=",
        "Snapshot=t37.inf",
        "Mode=HTML",
        LAST);

// Initialize the global done state variable, and start the async transaction variable
    done = 0;

lr_start_transaction("async-call");

// Define the request to be handled asynchronously, in this case a "?messages" call

// Specify the polling interval of 5 seconds

// Specify the callback functions that will be called when the response is returned.

// The callback functions are defined below.     web_reg_async_attributes("ID=Poll_0",
        "URL=http://ajaxify.com/run/wiki/content.php?messages",
        "Pattern=Poll",
        "PollIntervalMs=5000",
        "RequestCB=Poll_0_RequestCB",
        "ResponseBodyBufferCB=Poll_0_ResponseBodyBufferCB",
        "ResponseCB=Poll_0_ResponseCB",
        LAST);

// now make the async call.

// note that the script will not block on this call. processing will continue on past this step while the request is handles asynchronously
    web_url("content.php",
        "URL=http://ajaxify.com/run/wiki/content.php?messages",
        "Resource=0",
        "RecContentType=text/xml",
        "Referer=http://{host_ajaxify_com}/run/wiki/",
        "Snapshot=t38.inf",
        "Mode=HTML",
        LAST);

// To capture the response time of the async call, wait until the callback is called.

// Without this, the script would move past and complete the iteration before the callback is called.     while (done==0)
    {
        lr_think_time(1);
    }

// once the callback has been called, end the transaction to get the response time.      lr_end_transaction("async-call", LR_AUTO);

// stop the polling
   web_stop_async("ID=Poll_0",
        LAST);

    return 0;
}

/*
*    Callback Implementation
*
*
*/

int Poll_0_RequestCB()
{
    //enter your implementation for RequestCB() here

    return WEB_ASYNC_CB_RC_OK;
}

int Poll_0_ResponseBodyBufferCB(
    const char *    aLastBufferStr,
    int                aLastBufferLen,
    const char *    aAccumulatedStr,
    int                aHttpStatusCode)
{
    //enter your implementation for ResponseBodyBufferCB() here

// when the response is received, update the global variable
    done = 1;

// print out the response body and length
    lr_message("in Poll_0_ResponseBodyBufferCB response body callback");
    lr_message("in Poll_0_ResponseBodyBufferCB response body callback, lastBufferLen=%d", aLastBufferLen);

    return WEB_ASYNC_CB_RC_OK;
}

int Poll_0_ResponseCB(
    const char *    aResponseHeadersStr,
    int                aResponseHeadersLen,
    const char *    aResponseBodyStr,
    int                aResponseBodyLen,
    int                aHttpStatusCode)
{
    //enter your implementation for ResponseCB() here

    lr_message("in Poll_0_ResponseCB response callback, headerLen=%d, bodyLen=%d", aResponseHeadersLen, aResponseBodyLen);
    lr_message("in Poll_0_ResponseCB response callback, header=%s", aResponseHeadersStr);
    lr_message("in Poll_0_ResponseCB response callback, body=%s", aResponseBodyStr);

    return WEB_ASYNC_CB_RC_OK;
}

Console Output

Running Vuser...

Starting iteration 1.

Notify: max connections per server : 6

Starting action Action.

Action.c(16): web_url("wiki") started [MsgId: MMSG-26355]

Action.c(16): Redirecting "http://ajaxify.com/run/wiki" (redirection depth is 0) [MsgId: MMSG-26694]

Action.c(16): To location "http://ajaxify.com/run/wiki/" [MsgId: MMSG-26693]

Action.c(16): Found resource "http://ajaxify.com/run/Lib/css/demo.css" in HTML "http://ajaxify.com/run/wiki/" [MsgId: MMSG-26659]

Action.c(16): Found resource "http://ajaxify.com/run/wiki/wiki.css" in HTML "http://ajaxify.com/run/wiki/" [MsgId: MMSG-26659]

Action.c(16): Found resource "http://ajaxify.com/run/Lib/js/util.js" in HTML "http://ajaxify.com/run/wiki/" [MsgId: MMSG-26659]

Action.c(16): Found resource "http://ajaxify.com/run/Lib/js/ajaxCaller.js" in HTML "http://ajaxify.com/run/wiki/" [MsgId: MMSG-26659]

Action.c(16): Found resource "http://ajaxify.com/run/wiki/wiki.js" in HTML "http://ajaxify.com/run/wiki/" [MsgId: MMSG-26659]

Action.c(16): Found resource "http://ajaxify.com/favicon.ico" in HTML "http://ajaxify.com/run/wiki/" [MsgId: MMSG-26659]

Action.c(16): Found resource "http://ajaxify.com/run/Lib/php/button.php" in HTML "http://ajaxify.com/run/wiki/" [MsgId: MMSG-26659]

Action.c(16): web_url("wiki") was successful, 22491 body bytes, 2152 header bytes, 24 chunking overhead bytes [MsgId: MMSG-26385]

Action.c(26): Notify: Transaction "polling" started.

Action.c(41): web_reg_async_attributes started [MsgId: MMSG-26355]

Action.c(41): web_reg_async_attributes was successful [MsgId: MMSG-26392]

Action.c(50): web_url("content.php") started [MsgId: MMSG-26355]

Action.c(50): "ID=poll_0" && "Pattern=Poll" && "PollIntervalMs=5000" now applied to URL="http://ajaxify.com/run/wiki/content.php?messages" (RelFrameId=1, Internal ID=10) [MsgId: MMSG-35172]

Action.c(50): Retaining cross-step download of URL="http://ajaxify.com/run/wiki/content.php?messages" (RelFrameId=1, Internal ID=10) [MsgId: MMSG-27658]

Action.c(50): web_url("content.php") was successful, 0 body bytes, 0 header bytes [MsgId: MMSG-26386]

Action.c(62): lr_think_time: 1.00 seconds.

in Poll_0_ResponseBodyBufferCB response body callback

in Poll_0_ResponseBodyBufferCB response body callback, lastBufferLen=928

in Poll_0_ResponseBodyBufferCB response body callback

in Poll_0_ResponseBodyBufferCB response body callback, lastBufferLen=0

in Poll_0_ResponseCB response callback, headerLen=319, bodyLen=928

in Poll_0_ResponseCB response callback, header=HTTP/1.1 200 OK

Server: nginx/0.8.53

Date: Thu, 01 Nov 2012 21:18:42 GMT

Content-Type: text/xml

Transfer-Encoding: chunked

Connection: keep-alive

X-Powered-By: PHP/5.3.5-1ubuntu7.11

Expires: 0

Last-Modified: Thu, 01 Nov 2012 21:18:42 GMT

cache-control: no-store, no-cache, must-revalidate

Pragma: no-cache

in Poll_0_ResponseCB response callback, body=<messages> <message>

<lastAuthor>lastAuthor</lastAuthor>

<content>Wonder%20Wonder%20ffff%0AStuff%20here%20for%20123fdsfd%0Atest%0Avbnvytytry%0Aokadfasdf%0Artyry%0Artyryry%0Arytry%0Adfgvdfg%0A%0Asdfsad%0A%0Asdfsd%0A%0Aghghhgggh%0A%0Atesteste%0A%0AZe%20woiauha%0A%20df%0A%0Axcvx%0AHello%20friends%21%0Ahello%20folks%0Ahi%0Ajiadsasd%0A%0A%0Azzz</content>

</message> <message>

<lastAuthor>lastAuthor</lastAuthor>

<content>ABC%0Aklljljl%0Ak%3Bk%3B%3Bk%3B%0Aggugj%0A%0Affff%0A%0Aasdf%0A%0Abla%0Aqwe%0Aqweqwe%0Ajnknknkjkvfgh%0A</content>

</message> <message>

<lastAuthor>lastAuthor</lastAuthor>

<content>This%20is%20line%201%0AThis%20is%20line%202.%0AEnd%0A.%0Adffdfg123123123%0Aawgaw%0Afsdf%0Atestes%0Aasdfadf%0Aadsasd</content>

</message></messages>

Action.c(62): Issuing a "POLL" request for conversation with ID="poll_0" and "PollIntervalMs=5000". Scheduling due at t=13494, URL="http://ajaxify.com/run/wiki/content.php?messages" [MsgId: MMSG-35169]

Action.c(62): "ID=poll_0" && "Pattern=Poll" && "PollIntervalMs=5000" now applied to URL="http://ajaxify.com/run/wiki/content.php?messages" (RelFrameId=, Internal ID=11) [MsgId: MMSG-35172]

Action.c(67): Notify: Transaction "polling" ended with "Pass" status (Duration: 4.0431 Think Time: 1.8491 Wasted Time: 0.0121).

Action.c(69): web_stop_async started [MsgId: MMSG-26355]

Action.c(69): Notify: Deleting Conversation Information with ID="poll_0"

Action.c(69): Aborting download of URL "http://ajaxify.com/run/wiki/content.php?messages" (RelFrameId=, Internal ID=11) of conversation with ID="poll_0" [MsgId: MMSG-35167]

in Poll_0_ResponseBodyBufferCB response body callback

in Poll_0_ResponseBodyBufferCB response body callback, lastBufferLen=0

in Poll_0_ResponseCB response callback, headerLen=0, bodyLen=0

in Poll_0_ResponseCB response callback, header=

in Poll_0_ResponseCB response callback, body=

Action.c(69): web_stop_async was successful [MsgId: MMSG-26392]

Ending action Action.

Ending iteration 1.

Ending Vuser...

Starting action vuser_end.

Ending action vuser_end.

Vuser Terminated.

Loadrunner Asynchronous Results Polling

2012-10-23T16:30:00.000-07:00

Some user action trigger asynchronous server-side operations. The user can then be forced to check for results periodically by polling the server. The following script gives an example of how to do this as follows:

Define variables to specify polling interval and polling timeout.
Each polling interval, make the call to the server and check the results.
If the server has returned the finished results, end the polling loop and pass the transaction.
Otherwise, wait for the next polling interval and repeat.
If the timeout is hit, end the polling loop and fail the transaction.

Script

Action()
{
int done = 0;
int pollIntervalSec = 1;
int timeoutSec = 3;
int secWaited = 0;
char *response, *expectedResponse;

expectedResponse = "abc";

lr_start_transaction("wait_for_data");

// poll the site until expected response is received or timeout is reached
while (done==0)
{
// capture response information
  web_reg_save_param("responseParam",
"LB=Control: ",
"RB=max",
LAST );

// hit the page to be polled
  web_url("Test",
"URL=http://www.google.com",
"Resource=0",
"RecContentType=text/html",
"Snapshot=t1.inf",
LAST);

  // Save respone to string
response = lr_eval_string(lr_eval_string("{responseParam}"));

// check string contents to see if done
if(strcmp(response,expectedResponse)==0)
{
done=1; // set flag to indicate success
lr_message("Found expected response=%s", response);
lr_end_transaction("wait_for_data", LR_PASS);
}

  // increment time waited
secWaited = secWaited + pollIntervalSec;

  // check for timeout
if (secWaited > timeoutSec)
{
done = 1;
lr_end_transaction("wait_for_data", LR_FAIL);
lr_error_message("Wait for data timed out, took longer than %d seconds", timeoutSec);
}
lr_think_time(pollIntervalSec);
}

return 0;
}

Console Output

Starting action Action.
Action.c(11): Notify: Transaction "wait_for_data" started.
Action.c(15): Registering web_reg_save_param was successful [MsgId: MMSG-26390]
Action.c(20): Found resource "http://www.google.com/intl/en_ALL/images/srpr/logo1w.png" in HTML "http://www.google.com" [MsgId: MMSG-26659]
Action.c(20): Warning -26376: Requested parameter "responseParam" found in 2 different pages/frames. Use web_reg_save_param with more restrictive LB/RB/RelFrameId [MsgId: MWAR-26376]
Action.c(20): Warning -26373: Parameter "responseParam" saved from a resource (URL="http://www.google.com/intl/en_ALL/images/srpr/logo1w.png") [MsgId: MWAR-26373]
Action.c(20): web_url("Test") highest severity level was "warning", 12282 body bytes, 1071 header bytes [MsgId: MMSG-26388]
Action.c(48): lr_think_time: 1.00 seconds.
Action.c(15): Registering web_reg_save_param was successful [MsgId: MMSG-26390]
Action.c(20): Resource "http://www.google.com/intl/en_ALL/images/srpr/logo1w.png" is in the cache already and will not be downloaded again [MsgId: MMSG-26655]
Action.c(20): web_url("Test") was successful, 4952 body bytes, 400 header bytes [MsgId: MMSG-26386]
Action.c(48): lr_think_time: 1.00 seconds.
Action.c(15): Registering web_reg_save_param was successful [MsgId: MMSG-26390]
Action.c(20): Resource "http://www.google.com/intl/en_ALL/images/srpr/logo1w.png" is in the cache already and will not be downloaded again [MsgId: MMSG-26655]
Action.c(20): web_url("Test") was successful, 4952 body bytes, 224 header bytes [MsgId: MMSG-26386]
Action.c(48): lr_think_time: 1.00 seconds.
Action.c(15): Registering web_reg_save_param was successful [MsgId: MMSG-26390]
Action.c(20): Resource "http://www.google.com/intl/en_ALL/images/srpr/logo1w.png" is in the cache already and will not be downloaded again [MsgId: MMSG-26655]
Action.c(20): web_url("Test") was successful, 4952 body bytes, 224 header bytes [MsgId: MMSG-26386]
Action.c(45): Notify: Transaction "wait_for_data" ended with "Fail" status (Duration: 4.1903 Think Time: 3.0017 Wasted Time: 0.6545).
Action.c(46): Error: Wait for data timed out, took longer than 3 seconds
Action.c(48): lr_think_time: 1.00 seconds.
Ending action Action.

Virtualization Performance Testing

2012-10-22T16:02:00.002-07:00

Virtualization technologies (such as VMware, Parallels, Xen, KVM, Waratek, etc.) have become very popular for good reasons, including but not limited to the following:

Application density can be increased
Server resource usage can be maximized
Hardware costs can be reduced many-fold
The number of servers required to run the same load can be reduced
Applications become more portable

It is critical to do performance, load, and stress testing of a virtualization solution before rolling it out for several reasons:

Different applications behave differently in a virtualized environment and some are more suitable than others
Performance or stability could be affected in a virtualized environment
Virtual machine sizing can drastically affect application behavior
Application configuration can be different when run in a virtualized environment.

This post gives a brief outline of how to do performance, load and stress testing of a virtualization solution.

Include online and batch test cases as well as administrative operations
Test bare metal (physical server) as a baseline to be compared to virtualization results

See how many instance of the application can be run on bare metal
Push bare metal up to server capacity

Test virtualization

Run VMs on the same bare metal server or an equivalent one
Push one VM up to capacity, then two VMs, then three VMs, etc., up to the highest density desired.
Capture hypervisor server resource usage metrics (cpu, memory, disk, network)
Verify that VM performance compares reasonably relative to bare metal
Verify that VM capacity compares reasonably relative to bare metal
Verify that VM application stability compares reasonably relative to bare metal
If performance or stability is not acceptable, see if application tuning is needed or virtual machine tuning is needed.
Include stability tests in which high load is applied for an extended period of time.
Perform administrative operations while system is under high load.
Once performance and stability are acceptable, publish the results and the tuning and configuration needed to achieve acceptable results.

Loadrunner How to Read Parameters From Javascript

2012-10-22T15:48:00.001-07:00

Sometimes it is necessary to read data from the contents of a javascript file rather than an html page. The javascript may have certain variables created at compile time that it is useful to correlate. Because the javascript file may show up as extra resources in an http call, the contents of the file are not visible to web_reg_save_param, etc. However, by adding an additional call, the javascript can be read as follows:

Get the .js file with a web_url call
Set content type to "text/js"
Set resource=1

The following gives an example of the method described.

Script

Action()
{
web_reg_save_param("jsText",
"LB=",
"RB=",
LAST );

web_url("Test-Read-JS-File",
"URL=https://test.server.com/scripts/test.js",
"Resource=1",
"RecContentType=text/js",
"Snapshot=t1.inf",
LAST);

return 0;
}

Console Output

Starting action Action.
Action.c(4): Registering web_reg_save_param was successful [MsgId: MMSG-26390]
Action.c(9): Notify: Saving Parameter "jsText = HTTP/1.1 200 OK\r\nAccept-Ranges: bytes\r\nCache-Control: max-age=2592000\r\nContent-Type: application/x-javascript; charset=utf-8\r\nDate: Mon, 22 Oct 2012 22:39:40 GMT\r\nExpires: Wed, 21 Nov 2012 22:39:40 GMT\r\nLast-Modified: Fri, 19 Oct 2012
...
Action.c(9): web_url("Test-Read-JS-File") was successful, 614175 body bytes, 321 header bytes [MsgId: MMSG-26386]
Ending action Action.

Dumping Very Large Java Heaps

2012-09-14T15:52:00.002-07:00

When a java application has either a memory leak or much higher than expected memory utilization, it is necessary to obtain heap information to identify the source of the problem. A heap dump is ideal because it can then be analyzed using various tools. However, with very large java heaps, perhaps > 100GB, a heap dump may be impractical for several reasons:

the heap dump may crash the java process before completing
the heap dump may hang indefinitely
there may not be enough disk space to accomodate the dump
the dump may be so large that analysis tools are unable to process it

One solution to this scenario is to use the jmap utility to obtain a heap dump histogram from the running process. This appears to be very lightweight, completing quickly on very large heaps and generating a very small summary analysis file that can be used for troubleshooting.

The syntax for doing this is the following, where <pid> is the process id of the java process.

jmap -histo <pid>

The output is a very nice summary showing, for each class in the heap, the class name, the number of instances, and the size in bytes, for example as follows:

num #instances #bytes class name

----------------------------------------------

1: 70052 11118624 <constMethodKlass>

2: 70052 8422160 <methodKlass>

3: 6320 8258472 <constantPoolKlass>

4: 6320 6117216 <instanceKlassKlass>

5: 116656 5732520 <symbolKlass>

6: 17467 5729824 [I

7: 5682 5050352 <constantPoolCacheKlass>

8: 57275 4818512 [C

9: 24818 2660384 [B

10: 59327 1898464 java.lang.String

11: 2847 1766720 [J

12: 2978 1542008 <methodDataKlass>

13: 11687 797256 [S

14: 13307 706440 [Ljava.lang.Object;

15: 6777 704808 java.lang.Class

16: 18904 604928 java.util.HashMap$Entry

17: 10088 522512 [[I

18: 5736 499408 [Ljava.util.HashMap$Entry;

19: 12838 410816 java.util.Hashtable$Entry

20: 5580 267840 java.util.HashMap

21: 428 249952 <objArrayKlassKlass>

22: 5888 235520 java.util.concurrent.ConcurrentHashMap$Segment

23: 6243 199776 java.util.concurrent.locks.ReentrantLock$NonfairSync

24: 5888 146544 [Ljava.util.concurrent.ConcurrentHashMap$HashEntry;

...

3029: 1 16 sun.awt.X11.XToolkit$4

3030: 1 16 java.util.Collections$EmptyIterator

3031: 1 16 com.sun.tools.visualvm.core.explorer.ExplorerContextMenuFactory

3032: 1 16 sun.reflect.generics.tree.TypeVariableSignature

3033: 1 16 sun.awt.X11.XKeyboardFocusManagerPeer$1

3034: 1 16 org.openide.xml.EntityCatalog$Forwarder

Total 714547 74730032

Loadrunner Convert To Unicode or UTF-8

2012-09-14T12:40:00.001-07:00

The following shows how to convert strings in Vugen to unicode or UTF-8, which is necessary for certain applications with globalization functionality.

Script

Action()
{
char *converted_buffer_unicode = NULL;

// convert to unicode
lr_convert_string_encoding("Text to convert to unicode",
LR_ENC_SYSTEM_LOCALE,
LR_ENC_UNICODE,
"paramUnicode");

// convert to UTF-8
lr_convert_string_encoding("Text to convert to utf8",
LR_ENC_SYSTEM_LOCALE,
LR_ENC_UTF8,
"paramUtf8");

return 0;
}

Console Output

Running Vuser...
Starting iteration 1.
Starting action Action.
Action.c(6): Notify: Saving Parameter "paramUnicode = T\x00e\x00x\x00t\x00 \x00t\x00o\x00 \x00c\x00o\x00n\x00v\x00e\x00r\x00t\x00 \x00t\x00o\x00 \x00u\x00n\x00i\x00c\x00o\x00d\x00e\x00\x00\x00".
Action.c(12): Notify: Saving Parameter "paramUtf8 = Text to convert to utf8\x00".
Ending action Action.
Ending iteration 1.

How to Test the Stability of an Application

2012-09-13T17:00:00.001-07:00

Testing the stability of an application is critical. It can prevent system outages by identifying problems before they occur in production. Outages can severely damage a business, in some cases permanently. The following outline provides a reasonable template for testing application stability.

Ramp load up incrementally to the breaking point of the system. Do not stop at expected peak load because bursts or unexpected traffic can entail load far higher than anticipated.

Load should cover critical dimensions such as transaction rate/throughput, connections, concurrent users, range of use cases/functionality
When the application breaks, investigate what broke

If the test infrastructure broke (test client capacity hit, test network capacity hit, test case crashed, etc.), the test infrastructure must be repaired so that the application is what breaks, not the test infrastructure.
If the application broke, diagnose the type of breakage and what broke.
Is breakage recoverable?
Does breakage affect already connected users, or just block new users?
Did the application code break (errors, deadlocks, thread blocking, etc.)?
Was a system resource limit hit (cpu, memory, network, disk)?
If system resource limits were not hit, does the application need to be fixed so that it is not the bottleneck? The system should scale up so that system limits are hit, whether CPU, network, disk I/O, or network bandwidth.
Did a downstream service break?

How can the downstream service be improved to provide more capacity and stability?

Did the system just slow down, remaining functional?
Is a restart required, and what must be restarted (services, server, downstream services, etc.)?
Can the system be scaled out or scaled up to improve the capacity?

If not, why not? Is there an architectural limitation preventing further scalability? How can scalability be improved?

From the test determine the peak capacity of the application and verify that proper production monitoring is in place to detect this threshold.

Run at near peak capacity for an extended period of time (this could be one day or more depending on uptime requirements)

Is the application stable when run for a long time or does it eventually crash?

Why does it crash?

Does performance degrade over time?

Why does it degrade?

Perform administrative operations that may need to be performed during production usage while system is near peak load.

Is the system stable when this happens?

Perform the full suite of functional tests while the system is near peak load.

Is the system stable when this happens?

Document the results of the test carefully. Do not ignore crashes and instability. Spend the time and effort to understand the behavior and harden the application to behave well under any conditions, anticipated or not.

Loadrunner Unique Names

2012-09-13T16:10:00.002-07:00

It is useful to be able to create human-readable unique names to be used for filenames, database keys, logging, etc. One way to do this is to create a string with the following information:

load generator name
vuser id
iteration number
timestamp

This can be done easily as follows:

get load generator name using lr_get_host_name()
get vuser id using lr_whoami()
get iteration number using a parameter of type iteration
get current timestamp using lr_save_datetime()

The following script shows how to do this.

Script

Action()

{

int id

char *host;

// get load generator name

host = lr_get_host_name( );

//lr_output_message("Host: %s", host);

// get vuser id

lr_whoami(&id, NULL, NULL);

//lr_message( "Vuser id: %d", id);

// for iteration add a parameter named "Iteration" of type Iteration

//lr_output_message(lr_eval_string("Iteration: {Iteration}"));

// get timestamp, formatted as wanted

lr_save_datetime("%m-%d-%Y-%I%M%S%p", DATE_NOW, "now");

//lr_output_message(lr_eval_string("Time: {now}"));

// now generate the nice, readable unique id

lr_output_message(lr_eval_string("Host-%s-VuserId-%d-Iteration-{Iteration}-Time-{now}"),host, id);

return 0;

}

Output

Action.c(20): Host-generator02-VuserId-1-Iteration-1-Time-09-13-2012-035856PM [MsgId: MMSG-17999]

Action.c(20): Host-generator02-VuserId-2-Iteration-1-Time-09-13-2012-035856PM [MsgId: MMSG-17999]

Action.c(20): Host-generator02-VuserId-1-Iteration-2-Time-09-13-2012-035857PM [MsgId: MMSG-

Action.c(20): Host-generator02-VuserId-2-Iteration-2-Time-09-13-2012-035857PM [MsgId: MMSG-17999

Action.c(20): Host-generator02-VuserId-1-Iteration-3-Time-09-13-2012-035858PM [MsgId: MMSG-17999]

Loadrunner Charting Custom Metrics

2012-09-13T15:36:00.002-07:00

In Loadrunner, you can chart your own custom metrics easily by using the function lr_user_data_point. These could include calls to the server to collect system stats, application metrics based on responses, or anything at all. The custom metrics are then available in Loadrunner Analysis. The following provides an example:

Script

double getMyMetric();

Action()
{
double mymetric;
int i;
for (i=0;i<100;i++) {

mymetric = getMyMetric();
lr_user_data_point("mymetric", mymetric);
lr_log_message( "--- Added custom metric value = %f", mymetric );
}
return 0;
}

double getMyMetric()
{
int randomInt = (rand() % 100)+1; // Get a random number 1 - 100
double mymetric = randomInt / 100.0; // Return a double between 0 and 1
return mymetric;
}

Console Output

Running Vuser...
Starting iteration 1.
Starting action Action.
Action.c(10): Notify: Data Point "mymetric" value = 0.4800.
--- Added custom metric value = 0.480000
Action.c(10): Notify: Data Point "mymetric" value = 0.7900.
--- Added custom metric value = 0.790000
...

Analysis Output

The custom metric is then available in analysis:

A chart can be generated showing the trend of the custom data points added during the test:

Loadrunner Current Timestamp

2012-09-13T15:03:00.003-07:00

In Vugen, it is helpful to include a datetime with log messages, either informational or errors. This can be done very easily using the lr_save_datetime function. The timestamp can also be formatted in many different ways using the format codes commented out in the script below. The following script shows how this can be done:

Script

Action()
{
// handle an event such as an error or important message including a timestamp
lr_save_datetime("%m/%d/%Y %I:%M:%S %p", DATE_NOW, "now");
lr_output_message(lr_eval_string("{now}: My important message here."));

// Format codes for lr_save_datetime
// %a day of week, using locale's abbreviated weekday names
// %A day of week, using locale's full weekday names
// %b month, using locale's abbreviated month names
// %B month, using locale's full month names
// %c date and time as %x %X
// %d day of month (01-31)
// %H hour (00-23)
// %I hour (00-12)
// %j number of day in year (001-366)
// %m month number (01-12)
// %M minute (00-59)
// %p locale's equivalent of AM or PM, whichever is appropriate
// %S seconds (00-59)
// %U week number of year (01-52), Sunday is the first day of the week. Week number 01 is the first week with four or more January days in it.
// %w day of week; Sunday is day 0
// %W week number of year (01-52), Monday is the first day of the week. Week number 01 is the first week with four or more January days in it.
// %x date, using locale's date format
// %X time, using locale's time format
// %y year within century (00-99)
// %Y year, including century (for example, 1988)
// %Z time zone abbreviation
// %% to include the "%" character in your output string

return 0;
}

Console Output

Running Vuser...
Starting iteration 1.
Starting action Action.
Action.c(29): 09/13/2012 02:56:41 PM: My important message here.
Ending action Action.
Ending iteration 1.

Performance Testing ROI and Black Swans

2012-08-27T14:05:00.002-07:00

What return on investment/ROI can be expected from performance testing? There are two categories of "return" for performance and stability testing.

One category of return is a simple, quantifiable return in which performance testing results allow the amount of hardware required to be reduced in a couple of ways:

Application tuning and optimization allowing the same amount of hardware to handle additional traffic
Proof of hardware overcapacity, showing that a reduced amount of hardware would be sufficient to handle peak traffic, allowing hardware inventory to be reduced

The second category of return is not a return so much as an insurance policy, or protection against a fat tail or black swan event. In this case, you are protecting yourself against system stability bugs whose consequences can be absolutely catastrophic, up to the complete destruction of the business.

Consider the example of Knight Capital's botched software rollout on August 1st, 2012. The rollout triggered unexpected trades that cost the firm $440 million, depleting its operating capital. This weakened position allowed outside investors to take a controlling 70% stake in the company as terms of its bailout.

By doing performance and stability testing, catastrophic stability bugs may be missed due to limitations of the test environment or test data, or failure to anticipate the nature of production behavior leading to the disaster. However, if a catastophic stability bug is discovered and fixed, which happens regularly, a black swan event has been quietly and successfully sidestepped. The value is avoiding a devastating black swan event that brings down the company through loss of customers, loss of reputation, lawsuits, takeovers, etc. Not to mention more individual losses such as loss of job, bonus, promotion, career, etc. The cost of the testing is fixed and predicable, simply the cost of supporting ongoing performance testing, in effect the insurance policy premiums protecting against the black swan.

How To Add a Timestamp to Each Line of Output on Linux

2012-08-24T10:16:00.001-07:00

For performance monitoring on linux, you typically would like your shell script metrics and statistics that are logged periodically to include the timestamp with each line output. That way, the information can later be correlated with other system events such as event log entries or system errors. There are two basic scenarios.

Your shell script is echoing information to standard output periodically in some loop
You are just calling a program such as vmstat directly that outputs information periodically

Adding a timestamp in the two scenarios can be handled easily as follows:

Monitoring Loop

If your monitoring script includes a loop that is outputting stats periodically, a timestamp can be added to each line by capturing the output of the "date" command and then adding that information to the output line.

The output of the date command can be captured by using forward single quotes, as follows:

savedDate = `date`

Here is an example of a script making use of this technique:

# output stats every $1 seconds until stopped

if [ "$1" == "" ] ; then

echo "syntax= .stats.sh <intervalSeconds>"

exit

time=$1

echo "Time , QueriesPerSechod" > mysql-stats.log

while :

qps=`mysql -u mysql -e "show status" | awk '{if ($1 == "Queries") print $2}'`

date=`date`

echo "$date , $qps" >> mysql-stats.log

sleep $time

done

Here is an example of the output:

Time , QueriesPerSecond

Wed Aug 8 16:11:58 PDT 2012 , 3029

Wed Aug 8 16:12:08 PDT 2012 , 18195

Wed Aug 8 16:12:18 PDT 2012 , 18903

...

Direct Output

If you are just calling an app or script such as vmstat, iostat, etc., that outputs stats periodically for you, you can achieve the same effect by piping the command through an app that prepends a timestamp to each line. For example, to prepend timestamps to the output from vmstat, free, and iostat, you would do the following, depending on a script "timestamp.sh" with the timestamp prepend behavior:

# free

free -g -s 10 | ./timestamp.sh > free.log &

# vmstat

vmstat 10 | ./timestamp.sh > vmstat.log &

# iostat

iostat 10 | ./timestamp.sh > iostat.log &

This would give output such as the following:

07/23/12 10:41:44,procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----

07/23/12 10:41:44, r b swpd free buff cache si so bi bo in cs us sy id wa st

07/23/12 10:41:44, 6 0 2736 3381052 505844 159601296 0 0 62 119 1 1 6 1 93 0 0

07/23/12 10:41:54, 2 0 2736 3358836 505900 159601728 0 0 102 25 640 414 1 0 99 0 0

07/23/12 10:42:04, 7 0 2736 3329736 505948 159601936 0 0 9 32 927 1263 1 0 98 0 0

The timestamp.sh script is as follows:

#!/usr/bin/perl

#while (<>) { print localtime() . ": $_"; }

while (<>)

{

($sec,$min,$hour,$mday,$mon,$year,$wday,$yday,$isdst) = localtime(time);

$secpad = sprintf( "%02d", $sec );

$minpad = sprintf( "%02d", $min );

$hourpad = sprintf( "%02d", $hour );

$monpad = sprintf( "%02d", $mon );

$mdaypad = sprintf( "%02d", $mday );

$yearpad = sprintf( "%02d", ($year + 1900) % 100 );

$time = "$monpad\/$mdaypad\/$yearpad $hourpad:$minpad:$secpad";

print $time . ",$_" ;

#17/04/112 16:40:14

}

How to Measure Response Times in Java

2012-08-14T10:39:00.002-07:00

This post describes how to measure response time in Java. You can use either System.currentTimeMillis() or System.nanoTime() depending on what response times you will be recording.

System.currentTimeMillis is accurate to 1 millisecond, so is typically appropriate if you have response times on the order of magnitude of 1 second or more. Using currentTimeMillis, you could report results in seconds with three decimals of precision, such as 1.205 seconds, or results in milliseconds with zero decimals of precision, such as 1205 milliseconds.

nanoTime is typically appropriate if you want to report response times with greater precision than milliseconds, useful in cases in which differences of a fraction of a millisecond or microsecond are needed.

The following java code sample shows how to capture the response time of a transaction using both currentTimeMillis and nanoTime, showing the results in milliseconds with three decimals of precision.

Code Sample

/**

* Created with IntelliJ IDEA.

* User: ehammer

import java.net.*;

import java.io.*;

public class TimerTest

{

public static final Double NANO_TO_MILLIS = 1000000.0;

public static void main(String[] args) throws MalformedURLException, IOException

{

// start timer

long nanoStart = System.nanoTime();

long milliStart = System.currentTimeMillis();

// do work to be timed

doWork();

// stop timer

long nanoEnd = System.nanoTime();

long milliEnd = System.currentTimeMillis();

// report response times

long nanoTime = nanoEnd - nanoStart;

long milliTime = milliEnd - milliStart;

reportResponseTimes(nanoTime, milliTime);

}

private static void reportResponseTimes(long nanoTime, long milliTime)

{

// convert nanoseconds to milliseconds and display both times with three digits of precision (microsecond)

String nanoFormatted = String.format("%,.3f", nanoTime / NANO_TO_MILLIS);

String milliFormatted = String.format("%,.3f", milliTime / 1.0 );

System.out.println("Milliseconds using nanoTime(): " + nanoFormatted);

System.out.println("Milliseconds using currentTimeMillis: " + milliFormatted);

}

private static void doWork() throws MalformedURLException, IOException

{

URL url = new URL("http://www.google.com/");

URLConnection conn = url.openConnection();

BufferedReader in = new BufferedReader(new InputStreamReader(conn.getInputStream()));

while (in.readLine() != null) {}

in.close();

}

Sample Output

Milliseconds using nanoTime(): 277.913

Milliseconds using currentTimeMillis: 278.000

Process finished with exit code 0

Walk Through

Timer is started as follows:

long nanoStart = System.nanoTime();

long milliStart = System.currentTimeMillis();

The transaction to be timed is then run.

The timer is stopped:

long nanoEnd = System.nanoTime();

long milliEnd = System.currentTimeMillis();

The difference between end and start is taken:

long nanoTime = nanoEnd - nanoStart;

long milliTime = milliEnd - milliStart;

Results are formatted in the desired precision, in this case as milliseconds with three decimals of precision (microsecond precision):

String nanoFormatted = String.format("%,.3f", nanoTime / NANO_TO_MILLIS);

String milliFormatted = String.format("%,.3f", milliTime / 1.0 );

Note that nanoTime results show microsecond precision, while currentTimeMillis shows results in 1 millisecond increments.

Recording Loadrunner Traffic in Fiddler

2012-08-13T14:02:00.004-07:00

It can be useful to capture loadrunner http traffic in fiddler. This can be useful, for example, for seeing the timeline of http requests, which ones are slow, what sort of parallelism exists, if any, etc. It can also be useful to compare the vugen timeline of requests to the same information captured directly from the browser, as vugen may not match browser behavior as expected, by serializing what is sent asynchronously in parallel by the browser, etc.

Vugen can be configured in Runtime Settings, Internet Protocol, Proxy, Use Proxy Server, address=localhost, port=8888.

You then put breakpoints in the script before and after the section you want to record, run the script in vugen to the first breakpoint (with logging disabled), start capturing traffic in fiddler, run the script to the second breakpoint and stop capturing traffic in fiddler. You can then see a visualization of the request pipeline in fiddler for your loadrunner traffic:

It is also a good idea to capture the traffic by running the script from the controller on the load generator to reduce vugen overhead. You will get a more compact and realistic pipeline that way.

You can then record the same transaction manually using the web browser for comparison to loadrunner.

LoadRunner Sub-Transactions

2012-07-05T10:49:00.002-07:00

Often in a loadrunner script, many transactions are of a common type, like "save" or "search" or "report_view". These common operations need to be aggregated for reporting purposes. You want to easily create a chart showing, for example "Search Response Time" or "Searches Per Second" or "Search Response Time (percentile)".

One easy way to do this is to run the following perl script which will take any transaction and wrap it in a second "sub-transaction" of the name input. For example, suppose you have the following in your Action.c:

lr_start_transaction("Search1");
...
lr_end_transaction("Search1", LR_AUTO);

...
...

lr_start_transaction("Search2");
...
lr_end_transaction("Search2", LR_AUTO);

Following running the script in the directory with your Action.c file, passing the parameter "search" ("perl lr-subtrans.pl search"), you would now have:

lr_start_transaction("Search1");
lr_start_transaction("search");
...
lr_end_transaction("search", LR_AUTO);
lr_end_transaction("Search1", LR_AUTO);
...
...

lr_start_transaction("Search2");
lr_start_transaction("search");
...
lr_end_transaction("search", LR_AUTO);
lr_end_transaction("Search2", LR_AUTO);

This would then allow very easy reporting of the aggregate search transaction. After running the script, you have to go in and remove the sub-transactions around transactions that are not relevant, like perhaps "login", "homepage", "back", etc.

Script

# lr-subtrans.pl
# Loadrunner add subtransaction script
#
#
use File::Copy;

$transname = $ARGV[0];
$actionfile = "Action.c";
$backupfile = "Action.c.bak";
$outfile = "Action.c.subtrans.txt";

if ($transname eq "-?" or $transname eq "/?" or $transname eq "-help" or $transname eq "/help" or $transname eq "")
{
die "USAGE: perl lr-subtrans.pl <transactionName> (Note: each transaction will be wrapped with a transaction named <transactionName>)\n";
}

copy($actionfile, $backupfile) or die "File cannot be copied.";

open (INFILE, $actionfile) or die "Can't open $actionfile";
open (OUTFILE, ">$outfile") or die "can't open $outfile";

while ($line = <INFILE>)
{
# Add server parameter and default check
if ($line =~ "lr_start_transaction")
{
print OUTFILE $line;
print OUTFILE "\tlr_start_transaction(\"$transname\"); \n";
}
# BIIT ID ("SESSION ID") RULE
elsif ($line =~ "lr_end_transaction")
{
print OUTFILE "\tlr_end_transaction(\"$transname\", LR_AUTO); \n";
print OUTFILE $line;
}
else
{
print OUTFILE $line;
}
}
close (INFILE);
close (OUTFILE);

# Copy Action.c.correlated.txt to Action.c
copy($outfile, $actionfile) or die "Copy failed: $!";

Reporting Response Times - Percentile Distributions and Trends

2012-06-04T15:45:00.004-07:00

Response time metrics can be very misleading. An average of 2 seconds can mask occasional very high values that could be relevant to performance goals. It can also mask cyclical trends. The same is true of reporting median or specific percentiles such as 95th percentile. An informative response time report should include two elements:

Response time percentile distribution
Response time trends with enough granularity to see spikes and patterns

Here is an example of these two elements:

Response Time Percentile Distribution

The distribution chart shows clearly what percentage of response times might be above the response time goal.

Response Time Trend

The trend chart shows clearly an upward trend over time, an important property that would be lost in any single response time metric. It also includes enough granularity to show the distribution pattern of response time spikes.