100
0
When attempting to find the response times of Portal pages, the first important question is to decide where you want to measure the times. Most people think of the response time at the client browser as the thing they want to measure. This is the most obvious and logical choice. However, it is also the hardest to measure and aggregate. The next place, which is easy to measure and aggregate, is at the WebServer (e.g. IHS, Apache) that serves the Portal Servers. This will be our measurement location in the Portal topology.
To measure response times in Apache or IHS, you need to change the LogFormat directive in “/HTTPServer/conf/httpd.conf” to include the %D directive. “%D” is the microsecond timer which measures response times. So, the default and revised LogFormat directives are as follows.
This is the default “out of the box” LogFormat directive:
“LogFormat "%h %l %u %t \"%r\" %>s %b" common”
This is the one I typically use:
“LogFormat "%h %l %u %t \"%r\" %>s %b %D microsecs %{was}e Cache_Control: %{cache-control}o Cache Age: %{Age}o" common”
Notice the “%D microsecs”. This is the response time monitor. I typically also include other directives as well. They are:
%{was}e: Logs the WebSphere server to which this request was routed. Useful for load balancing.
%{cache-control}o: Logs the “cache-control” header. Useful for seeing the cacheability of the response.
%{Age}o: Logs the “Age” header. Useful for seeing if the response was returned from the IHS cache.
Note that you also need a “CustomLog” directive for “common” to insure that this LogFormat directive gets used.
So, at this point, IHS (Apache) is configured to log all request/response times in the access_log file in the “logs” subdirectory of IHS. Note that this filename may be different if configured to be so.
So, now the process is just to examine the access log for the response times that one is interested in. In this case, we care about log response times. For most Web applications, greater than 4 seconds is considered long. So, a simple “grep” of the access logs will provide those responses. For reasons of simpler “grep” commands, I’ll start with response times greater than 10 seconds. Here is a sample “grep”:
grep "[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9] microsecs" access_log
Here is a sample line from the access_log file:
127.0.0.1 - - [04/Aug/2015:11:10:37 -0400] "GET /wps/myportal/!ut/p/z1/04_Sj9CPykssy0xPLMnMz0vMAfIjo8ziTT0NHT0svQ28_U1cTQwcXZ1CAnx9DQwM_I30wwkpiAJKG-AAjgZA_VFgJbhMcDeAKkDX6RRk5GQMlAdZQciSgtwIg0xPR0UAa1uCEQ!!/dz/d5/L2dBISEvZ0FBIS9nQSEh/ HTTP/1.1" 200 41215 6241394 microsecs aclfc19:10039 Cache_Control: no-cache, no-store, must-revalidate Cache Age: -
This “grep” looks for a character sequence with 8 digits (which includes 10 seconds and greater) followed by the string “microsecs”.
By using this basic pattern, one can get the long response times. If, for example, you want a sorted list of response times, you can rely on the fact that the response time is the 11th field in the access_log. So the command:
grep "[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9] microsecs" access_log | sort -k 11
will sort the list in increasing order of response time.
grep "[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9] microsecs" access_log | grep -v HEAD | sort -k 11
will strip out all the “HEAD” GET requests (used by health checkers like F5 and Edge) before sorting. Normally, HEAD requests are very, very fast so this is not usually needed.
Of course, we haven’t talked about which pages are long yet! That information is simply the beginning of each line returned by the “grep”. In this case, the page is “/wps/myportal/!ut/p/z2/04_Sj9CPykssy0xPLMnMz0vMAfIjo8ziTT0NHT0svQ28_U1cTQwcXZ1CAnx9DQwM_I30wwkpiAJKG-AajgZA_VFgJbhMcDeAKkDX6RRk5GQMlAdZQciSgtwIg0xPR0UAa1uCEQ!!/dz/d5/L2dBISEvZ0FBIS9nQSEh/”. However, except for the “/wps/myportal”, this doesn’t look like a recognizable page. If you want the URLs to indicate the page, you need to insure that every page and label in Portal has a “friendly” URL specified. That way, the full page name will appear in the URL. The information in the URL above after “!ut” is “state” information. This is decodable to the acutal page name as well but is beyond the scope of this paper.
