request processing time- JBoss and mod_jk

[nk83]

Hi

My web application architecture is: Apache 2 (as load balancer) + JBoss 3.2.3 + MySQL 5.0.19.

I want to: measure the request processing time (for every individual request) spent on the JBoss server only (i.e., excluding time spent on Web and database servers.    

I've been researching about how to log request processing time on an application tier only. I found *mod_JK logging*, *Apache's mod_log_config* and Tomcat *AccessLogValve* as two possible methods.

Using *mod_JK logging*: my understand mod_jk logging provides request processing time for each request and calculate as time difference between time when a request leaves the Apache server and time when the corresponding response received by the Apache server. Please correct me if this not accurate/correct.

Using Apache's mod_log_config model ([http://www.lifeenv.gov.sk/tomcat-docs/jk/config/apache.html][1]): by adding "%{JK_REQUEST_DURATION}n" in the LogFormat (the JKLogFile construct) construct see ([http://www.lifeenv.gov.sk/tomcat-docs/jk/config/apache.html). The "JK_REQUEST_DURATION" capture overall Tomcat processing time from Apache perspective.

The times (in the above cases) includes Tomcat/JBoss + MySQL processing time. It won't help in my case as it includes MySQL processing time- I want to record request processing time on JBoss only. Any suggestions/ideas are appreciated?

Using *AccessLogValve*: it can log "time taken to process request, in millis" by setting %D in the pattern attribute of the AccessLogValve XML construct. It is not very clear if this

- Time if this time is the time required by tomcat/JBoss to serve a

   request (e.g., allocate thread worker to handle it)  

- Time taken to process a request and send it to the database server

   (overall time on    Tomcat/JBoss server)

- Time taken to process a request by Tomcat/JBoss and send a response

   back to a Web server/client

Any idea/clue?

Or Any other better ways to measure processing time at JBoss server only for each individual request 

Thanks for your time   

  [1]: http://www.lifeenv.gov.sk/tomcat-docs/jk/config/apache.html

[jfclere]

The mod_jk JK_REQUEST_DURATION (%T in the JkRequestLogFormat) gives the overall time (network + request processing time).

%D in the AccessLogValve is "Time taken to process the request, in seconds" in fact that is the time to process the request after it has been processed by the AccessLogValve.

->NETWORK->CONNECTOR->THREAD->VALVE->SERVLET

^JK_REQUEST_DURATION

<-NETWORK<-CONNECTOR<-THREAD<-VALVE<-SERVLET

->NETWORK->CONNECTOR->THREAD->VALVE->SERVLET

^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^%D in the AccessLogValve

<-NETWORK<-CONNECTOR<-THREAD<-VALVE<-SERVLET

[nk83]

Thanks Jean-Frederic!

This means in my architecture the mod_jk JK_REQUEST_DURATION gives the overall time (overall network time + request processing time on JBoss +  request processing time on MySQL).

The AccessLogValve does not include the queuing time at the server and the thread worker allocation and processing as it starts recording the time after it has been processed by the AccessLogValve. This turns to be not accurate.

Another way I found is 

Using Tomcat's *RequestInfo* class ([http://tomcat.apache.org/tomcat-6.0-doc/api/org/apache/coyote/RequestInfo.html]): This class contains information about each request (check the link above please). It has a method updateCounters () which update statistical information about each request (including max, min and average processing time). Again this method includes the database processing time which I want to exclude. 

I  think using Tomcat's "RequestInfo" class (updateCounters () method) also will not include the queuing and thread processing times?

So mod_jk JK_REQUEST_DURATION gives overall time but I need to measure and deduct DB processing time to get request processing time on the application server only. This will likely add fairly considerable overhead for each request. 

I want to exclude DB processing time. Any other ways can be used to measure the request processing time on JBoss only (or at least with the network+ JBoss)?

Thank you

[jfclere]

The information from RequestInfo comes from before the valves and just after the thread "allocation".

You can't exclude the DB processing time except you log it in our application.

You are not telling any on the DB you use neitheir how you use it, there might be standard ways depend on the DB to get the information you need.

[nk83]

Yes, that's what I meant- logging/measuring the DB processin time for each request so I deduct it from the overall request processing time (measured from the mod_jk JK_REQUEST_DURATION) so I know the request processing time on Jboss (including the network trip between Apache and JBoss).

I'm using MySQL 5.0.19 on a separate server machine, connected to JBoss using JDBC. The application is e-commerce. 

The challenge here is that there would be 1 or more queries sent to MySQL to serve one request. How to correllate processing times of n quieries with the corresponding request.

Writing a low level code to capture queries processing times could be one solution, but most likely it add performance overhead. Is there any tool/way to capture MySQL processing time from JBoss (similar to mod_jk logging)  for each request?

[jfclere]

Depending on what the application is doing the accessLog valve results are probably related to the MySQL processing time.

[nk83]

Exactly, it depends on the application, workload patterns and request types..

Im' not sure if the accessLog valve results would log all such trips to the MySQL (total processing time of MySQL)..any pointers?

Thanks