Gotcha #7 - AppDynamics and the Mysterious Case of the Vanishing Cookie

Not much of a mystery today in this article (the answer is alluded to in the title) but the process of identifying the problem, discovering why it was a problem, and then fixing it was quite a challenge.

Today's Gotcha is about Rational Performance Tester (v8.5.1.2 for anyone interested) and a vexing problem with successful test execution.

The problem originally arose when we discovered that our tests weren't always succeeding. After executing a schedule we would consistently have a large number of pages that wouldn't have 100% success status codes (located on the Server Health Detail view). There would be a few with 100% success rate, but consistently nearly every page was hovering between 94 and 98%. In some larger tests this would drop further, into the 80's or high 70's, but even a simple low volume test would have most pages at less than 100%.

To get a better handle on why and when these page errors were happening, I added a new counter to the default Page Throughput / Page Hit Rate graph (Add/Remove Performance Counters --> Page Performance Counter... --> Status Code Successes --> Percent Page Status Code Success [for Interval]).

Suddenly we could see this wavering line appear on the graph that would start off at 100%, dip sharply at the beginning of the test, before returning back up near 100% and stay fluctuating in the high 90% range.

Baffling when the very same test scripts in the past against the same application would run at 100% without trouble. Doubly-baffling when running the script as a standalone would work perfectly fine.

Following the Clues

The first clue came when we decided to rerun one of our test schedules and monitor the Test Execution of a user thread. Since the failures were reasonably consistent across all pages, chances are we might be able to catch it in the act.

After a couple of hours of watching successful page responses, we caught one. Right from the beginning of a new test script - a page failure. And then another, and another, and so on until every single page in that script failed in order. And the next script. And the next... but then the fourth script, for no apparent reason, began returning successful responses again.

Digging into the error, the only message we could find was a "Failed substitution ^csrfToken=.*$" message followed by a cascade of 500 - Server Error responses. The csrfToken appears in the HTTP Response header as a "Set-Cookie" value from the server (you can find an explanation of its purpose here). And for some reason, it wasn't being found.

Except... inspecting the response of that very first page - the csrfToken was right where it should be. Further digging into the application logs showed the same thing - on occasion our test would be sending an invalid csrfToken - the recorded token - which happens when the substitution couldn't be made.

But it was right there in the Response Header - right where we expected it to be. Except, not quite...

Smoking Gun

It looked like it was right where it was supposed to be - in among a half-dozen other cookies being set by the server. But a careful comparison with the original recording showed that it was 1 line down. There was a NEW Set-Cookie value that was inserted in the list just ahead of the csrfToken.

Inspecting and comparing successful test executions with failed ones showed that this new mysterious cookie only appeared in the failed tests, and wasn't to be found in the successful ones.

The server was randomly inserting a new cookie in its response... some of the time. And it was enough, by shifting the order of the Set-Cookie headers for RPT fail when trying to identify the csrfToken.

The culprit was a cookie called ADRUM_BTs and it looks like the following:

Set-Cookie: ADRUM_BTs="R:0|s:f"; Version=1; Max-Age=30; Expires=...date...; Path=/; Secure

There was no consistency in when or where it would appear. It would show up for a script execution or three, then disappear once more.

Solution

It turns out that we weren't the only ones to run the Mysterious Case of the Vanishing Cookie - other people had identified ADRUM_BTs as playing havoc with their scripting efforts.

The cookie in question belongs to AppDynamics End User Monitoring javascript package, a tool that can be used to monitor user behaviour and web application performance from the user's perspective. It was a new feature in the AppDynamics package that had been turned on in our Performance Testing environment recently to try and improve our measurement capabilities.

In the end, there was no way to remove this new cookie or adjust the system to consistently distribute it. In order to get our Performance Testing back up and running we had to remove all End-user Monitoring components - and suddenly our vanishing cookie was gone for the last time.

ICPE 2015, Getting Published with ACM, and Performance Management

It has been a busy year so far.

For much of 2014 I had been working on some research around Web Page Performance and understanding users expectations, what the industry believed about response times and how fast was 'fast enough', and how that compared to the real world. What I ended up finding is that much of the research that had been done in this field was, frankly, worthless. Oh, there were good points to be found, some useful results, and valuable nuggets to be unearthed - but on the whole most results drew conclusions that were being interpreted far to generally or their methodology was deeply flawed.

In short, there was a gaping hole that was asking to be filled. And the question was, how fast is 'fast enough'?

The most valuable conclusions I could glean from published works were as follows:

1. Faster is better
2. For systems that don't need to rely on real-time feedback, <1s is fast enough to be seamless for most request-response human-computer interactions be it locally or over the web
3. People will happily wait longer if they are given responsive feedback while they are waiting
4. Consistency is important

But from a practical perspective, what kind of performance level should I be aiming for? Is 5s fast enough? What about 3s? Is average response time sufficient, or do we need to use something stricter?

These kinds of questions led me to doing the research that eventually resulted in writing a paper that in September 2014 I submitted and was accepted by the International Conference on Performance Engineering (ICPE 2015).

That research paper is now officially available online at the MNP Library Defining Standards for Web Page Performance (also available via the ACM Digital Library with the following Citation Link).

In February of 2015 I then got to travel to Austin TX to present my paper at the conference. I will post my thoughts about the conference and the trip in an upcoming post, but in short it was a wonderful experience, I got to meet a lot of amazing people, the presentations were fantastic and I learned quite a bit.

Now, I am pursuing expanding our service offerings as part of MNP's Technology Consulting Team by officially introducing Performance Management.

Performance Management is all about improving the success rate of projects with a technology component. Performance is often a consideration that exists only as an afterthought on projects, something that can be taken care of after the important functional work has been completed. That very thinking has led to some spectacular failures in the real world notably including the 2014 Examsoft debacle, the 2013 launch of Healthcare.gov, the 2008 Edinburgh Fringe Festival ticketing system failure, and the 2007 scrapping of the new UK General Register Office System.

Performance Management is about planning for success, it is about helping organizations invest in quality and avoid making the mistakes of the past. This is something that has become a bit of a passion of mine, a purpose, and I intend to spend a lot more time using this space to talk about performance in the future.

RPT Custom Code - Ensuring Unique Logins for Looping Tests

A problem I have encountered while performance testing business applications with Rational Performance Tester is the uniqueness of logins. Often, business applications contain logic that will prevent duplicate logins from multiple sources at the same time, or will have workflow control or session replication or persistence that will result in interference if the same login is being used by more than one thread at the same time. A quick workaround to this problem can be to ensure there is a large pool of available logins to reduce the possibility of duplicates, however this is not always possible if a system is using Active Directory or LDAP, or if it SSO enabled. So the challenge being faced is, how do we bind a unique login to each virtual user thread in our test for the duration of the test?

The first approach would be to adjust the settings on your login datapool. When you add a datapool to your test an option exists to "Fetch only once per user".

In theory, this would be sufficient to ensure each thread will have a unique login. However in practice it seems to be not quite so simple. In a test configuration that uses multiple agents "Open mode" must be set to "Segmented" otherwise each agent will have a complete copy of the same list of accounts, resulting in duplication. In order to use Segmented in this manner though, your datapool must be larger than the number of threads in order to ensure sufficient rows are available in each segment. (IBM recommends you have 2x the number of records as threads to ensure balanced segmentation).

Despite the theory, I have run into the problem of threads exiting prematurely in a multiple user group/multiple agent/infinite loop test configuration with the error message "End of datapool reached". This is not an error we should be seeing. Reviewing the saved response data demonstrated that each thread was correctly using a single unique login, but somehow the error was consistent.

While attempting to debug the issue, I tried setting the "Wrap when last row is reached" property. Although successful in preventing threads from exiting prematurely, the wrap property appears to override the fetch-once property, returning me to a state of duplicate logins. Unfortunately, IBM's documentation does a poor job of explaining how each of these datapool properties interact with one another, so in order to overcome this issue I turned to writing my own piece of custom code to manage my logins.

The following custom code solution binds threads to a specific login on first access, and thereafter will always return the same login identifier for each subsequent request. It also segments the login map into groups that can be manually accessed (by passing the group name as the first parameter) or automatically by setting the User Group Name in your schedule.

This code is simplified and has a few limitations.

1. Distinct Agent Segments - Each Agent must use a distinct User Group Name because static objects are not shared in memory between agents. If two agents are assigned to the same User Group then duplicate logins will occur.
2. Configurability - The segments and login lists are hardcoded in this code segment, this could be overcome by adding an option to read logins from a file (or other data storage)
3. Order - Logins will always be returned in the same order for each subsequent test run, a piece of randomization code would allow them to be shuffled.

package export; 

import java.util.Arrays; 
import java.util.HashMap; 
import java.util.List; 
import java.util.Map; 

import com.ibm.rational.test.lt.kernel.IDataArea; 
import com.ibm.rational.test.lt.kernel.services.ITestExecutionServices; 
import com.ibm.rational.test.lt.kernel.services.ITestLogManager; 
import com.ibm.rational.test.lt.kernel.services.IVirtualUserInfo; 
import com.ibm.rational.test.lt.kernel.services.RPTCondition; 

/** 
 * !!Warning!!: This code is NOT agent safe. Each unique set of segmentation identifiers MUST be isolated to a single agent for this code to work correctly 
 * @author grempel 
 */ 
public class UniqueLoginManager implements 
                com.ibm.rational.test.lt.kernel.custom.ICustomCode2 { 
        
        private static Map<String, List<String>> loginsBySegment = new HashMap<String, List<String>>(); 
        private static Map<String, String> loginsByThread = new HashMap<String, String>(); 
        private static Map<String, Integer> indexBySegment = new HashMap<String, Integer>(); 
        private static boolean initialized = false; 

        /** 
         * Initializes static login maps by segmentation 
         */ 
        private synchronized void init() { 
                if(!initialized) { 
                        loginsBySegment.put("GRP1", Arrays.asList(new String[]{"grp1_login1","grp1_login2","grp1_login3"...}));
                        loginsBySegment.put("GRP2", Arrays.asList(new String[]{"grp2_login1","grp2_login2","grp2_login3"...}));
                        loginsBySegment.put("GRP3", Arrays.asList(new String[]{"grp3_login1","grp3_login2","grp3_login3"...}));
                        indexBySegment.put("GRP1", 0); 
                        indexBySegment.put("GRP2", 0); 
                        indexBySegment.put("GRP3", 0); 
                        initialized = true; 
                } 
        } 
        
        /** 
         * Instances of this will be created using the no-arg constructor. 
         */ 
        public UniqueLoginManager() { 
        } 
        
        /** 
         * Returns the previous login if the thread has previously requested a login during this test execution. Otherwise retrieves the next login from the list, binds it to the thread, and returns it. 
         * @param segmentId 
         * @param thread 
         * @return String.class login 
         */ 
        public synchronized String getLogin(String segmentId, String thread) { 
                if(loginsByThread.containsKey(thread)) { 
                        return loginsByThread.get(thread); 
                } else { 
                        init(); 
                        List<String> logins = loginsBySegment.get(segmentId); 
                        Integer index = indexBySegment.get(segmentId); 
                        if(logins!=null && logins.size()>0 && index<logins.size()) { 
                                String login = logins.get(index); 
                                indexBySegment.put(segmentId, index+1); 
                                loginsByThread.put(thread, login); 
                                return login; 
                        } else { 
                                //fail 
                                return null; 
                        } 
                } 
        } 

        /** 
         * Generate and manage unique logins across multiple user threads and user-defined segments. 
         * Warning: This class is not thread-safe for a segmentation identifier that is distributed across multiple agents. Each segmentation identifier 
         * must exist on a single agent to avoid login duplication. 
         * @param String.class[] args - arg0 = segmentation identifier (optional, if not included will use the UserGroupName as segmentation identifier) 
         */ 
        public String exec(ITestExecutionServices tes, String[] args) { 
                String segmentId = null; 
                ITestLogManager tlm = tes.getTestLogManager(); 
                
                IDataArea dataArea = tes.findDataArea(IDataArea.VIRTUALUSER); 
                IVirtualUserInfo virtualUserInfo = (IVirtualUserInfo)dataArea.get(IVirtualUserInfo.KEY); 
                String user = virtualUserInfo.getUserName(); 
                
                //If arg[0] not provided, use the UserGroupName as the segmentation identifier 
                if(args.length<1) { 
                        segmentId = virtualUserInfo.getUserGroupName(); 
                } else { 
                        segmentId = args[0]; 
                } 
                
                String login = getLogin(segmentId, user); 
                if(login==null) { 
                        tlm.reportErrorCondition(RPTCondition.CustomCodeAlert); 
                        return null; 
                } 
                
                return login; 
        } 
}

RPT Custom Code - Saving Response Data

How to build datapools by extracting generated data from a system using custom code in Rational Performance Tester.

A major challenge that I encounter consistently as a Performance Engineer is priming a system with known, consistent data that I can feed into datapools and use for testing. There are a variety of ways to accomplish this: conversion processes, generation tools, database scripts, restore/upgrade processes, etc. However, a project that I have been working on recently has a variety of issues with these strategies. The database is automatically generated and nearly impossible to decipher, not to mention that it changes with each new code release. The second issue is that the data generation tools are not being kept up to date by the developers, so they are usually broken with each new release. These issues have led me to the point of using my performance testing tool (Rational Performance Tester v8.5.2) as a workaround data priming tool.

This plan has its own challenges, primary identifiers are all system generated - and the only way I can reliably access the data once it is generated is using those primary identifiers. Granted, there are ways to obtain this information once it exists in the system, but they involved days if not weeks of effort to extract and cleanse the data into a form that can be used effectively, and would require significant assistance from a developer to do so. A better way would be to process and extract the desired information from the responses themselves as it is being generated by RPT.

Currently RPT does not have any simple write-back mechanism for references during a test. There may exist a way using references and variables - but if it does it is well hidden beneath the primary strengths of the tool, which are load generation, data substitution, and response analysis. This led me to consider the question "How would I enhance the tool to let me extract response data?". Since RPT is an Eclipse-based tool and supports the addition of custom code and plug-ins it should be entirely feasible to write some code to extract whatever I wanted from it.

So that is what I did - the example and the code presented below is a very simple, bare-bones way of extracting a reference from a page response, passing it into a block of custom code, and writing it to a CSV file in a thread-safe manner that will allow you to import the generated CSV back into your project as a datapool source. There are dozens of ways I can think of to use this code and enhance it if you want to write to a database, do data transformation, correlating reference data with existing datapools, or producing multiple outputs - but this should be sufficient to get you started if you are encountering problems bridging that gap from theoretical to practical.

Step 1: Create a Custom Code Class
With your recorded test open, right-click your top-level test element and select "Add --> Custom Code".

Selecting the new Custom code element will show the Custom Code element details in the right-side pane that lets you enter a Class name (in the format: "package.Class"). If this is the first time you have created a Custom Code class - click the "Generate Code" button to create a basic default class implementation. If you already have the Custom Code class you want to use, skip down to Step 4 for adding an existing Custom Code element to your test case.

This will generate a simple Custom Code class that you can start using in your test.

package export; 

import com.ibm.rational.test.lt.kernel.services.ITestExecutionServices; 

/** 
 * @author unknown 
 */ 
public class Test implements 
                com.ibm.rational.test.lt.kernel.custom.ICustomCode2 { 

        /** 
         * Instances of this will be created using the no-arg constructor. 
         */ 
        public Test() { 
        } 

        /** 
         * For javadoc of ICustomCode2 and ITestExecutionServices interfaces, select 'Help Contents' in the 
         * Help menu and select 'Extending Rational Performance Tester functionality' -> 'Extending test execution with custom code' 
         */ 
        public String exec(ITestExecutionServices tes, String[] args) { 
                return null; 
        } 


}

To organize my library of custom code, I created a new Performance Test Project called "CustomCodeReference". If you create this project as a Performance Test Project it will automatically include all of the required RPT libraries in its build path. This will also allow me to export the project into a .jar file that I can import into other projects, or simply reuse it as a dependency in other Performance Testing projects as needed.

Step 2: Create a Singleton File Writer
Create a new class file that will be used by our custom code as the singleton file writer to manage file creation, access, and synchronization between threads. In this example I have created the class "export.ExportAdministrator" in my CustomCodeReference project to be my singleton file writer class. A suggested enhancement to this structure would be to create a dedicated Factory class that returns an instance of an interface to allow for multiple optional implementations such as a CSV file implementation, an XML file implementation, or a database implementation.

package export;

import java.io.File;
import java.io.FileWriter;
import java.text.DateFormat;
import java.text.SimpleDateFormat;

/**
 * @author grempel
 * @date 2014-03-27
 *
 * Singleton class with factory to manage thread-safe file export
 * Usage:
 *   Call ExportAdministrator.getInstance() to obtain object reference
 *   Use instance write() or writeln() to export to file
 */
public class ExportAdministrator {
private static ExportAdministrator instance = null;
private FileWriter fw = null;

public ExportAdministrator() {
//Build string writer
DateFormat df = new SimpleDateFormat("yyyy-MM-dd HH-mm-ss");
File file = new File("C:\\rpt-log\\" + df.format(System.currentTimeMillis()) + " output.csv");
try {
fw = new FileWriter(file);
} catch (Exception e) {
e.printStackTrace();
}
}

/**
* Retrieve singleton instance of writer.
*/
public static synchronized ExportAdministrator getInstance() {
if(instance==null) {
instance = new ExportAdministrator();
}
return instance;
}

/**
* Write string to file
*/
public synchronized String write(String str) {
if(fw!=null) {
try {
fw.write(str);
fw.flush();
return "true";
} catch (Exception e) {
return e.toString();
}
}
return "failed";
}

/**
* Write string to file and start a new line
*/
public synchronized String writeln(String str) {
if(fw!=null) {
try {
fw.write(str);
fw.write("\r\n");
fw.flush();
return "true";
} catch (Exception e) {
return e.toString();
}
}
return "failed";
}

/**
* Clean up open file references
*/
@Override
protected void finalize() throws Throwable {
if(fw!=null) {
fw.close();
}
super.finalize();
}

}

This class will generate a timestamped output file in the folder "C:\rpt-log\" on each agent that is running the test.

One note to make about the usage of this class. If you are using more than 1 virtual user to generate your data, you are best to compile the entire set of data you want to write to the file into 1 string before calling writeln(). If you attempt to call write() multiple times, you cannot guarantee that they will be sequential as another thread may have called the write() method in the meantime.

Step 3: Call File Writer from Custom Code
With our file writer (ExportAdministrator) singleton in place, we can now modify our custom code to submit whatever we want to write to that file. In this case I have created our Custom Code class called "export.ExportIdentifier" in my CustomCodeReference project.

This custom code expects 2 arguments to be passed to it, an output type: a simple text string that will allow you to group outputs based on the type of data being written - this allows you to reuse the code for multiple types of values in a single test; and an output value: the value you want to write. In addition to these, this custom code will also generate a timestamp that will be written to the file in order to determine the write operation sequence.

package export;

import com.ibm.rational.test.lt.kernel.services.ITestExecutionServices;
import com.ibm.rational.test.lt.kernel.services.ITestLogManager;
import com.ibm.rational.test.lt.kernel.services.RPTCondition;

/**
 * @author grempel
 * @date 2014-03-27
 * 
 * Usage:
 *   Add Custom Code reference to a test
 *   Set Class name = /CustomCodeReference/export.ExportIdentifier
 *   Add Arguments
 *     - Text: Value Type String
 *     - Text or Reference: Value String
 */
public class ExportIdentifier implements
com.ibm.rational.test.lt.kernel.custom.ICustomCode2 {
/**
* Instances of this will be created using the no-arg constructor.
*/
public ExportIdentifier() {
}

/**
* For javadoc of ICustomCode2 and ITestExecutionServices interfaces, select 'Help Contents' in the
* Help menu and select 'Extending Rational Performance Tester functionality' -> 'Extending test execution with custom code'
* @param String.class[] args - arg0 = value type, arg1 = value to write
*/
public String exec(ITestExecutionServices tes, String[] args) {
//Validate arguments
String type = null;
String value = null;
ITestLogManager tlm = tes.getTestLogManager();
if(args.length<=1) {
tlm.reportErrorCondition(RPTCondition.CustomCodeAlert);
return null;
}
type = args[0];
value = args[1];
Long timestamp = System.currentTimeMillis();

//Generate CSV string to write to file
String result = timestamp.toString() + "," + type + "," + value;

//Submit string to writer
String error = ExportAdministrator.getInstance().writeln(result);

//Catch errors and return to RPT for validation and handling
if(error.equalsIgnoreCase("true")) {
return result;
}

return error;
}

}

Step 4: Add Custom Code to a Test
To use this custom code in your test, add a Custom Code element to your test (see Step 1 for reference). Instead of generating a new class, we will be specifying our existing class in the Class Name field with the format: "/ProjectName/package.ClassName". In the above example this will be "/CustomCodeReference/export.ExportIdentifier".

Next we will add the arguments to the custom code element details. The first argument is the output type. Click the "Text" button on the right and specify the text to submit as the type. This can be different for each Custom Code element that you add to your test, but it works best as a hard-coded value in order to ensure it remains the same for each iteration.

Then click "Add" and select a data source object or reference to use as the output value. In this example I have set the output type to "TestAccountName" and the output value to the "Username" variable from my datapool. This example is redundant, I already have my usernames in a datapool - normally I would insert the custom code after a page response that contains some data that I want to write to a file, and select a reference instead.

This will now allow me to export any generated data that exists in the response record to an external source.