What dose "%... D The time taken to serve the request, in microseconds. "mean?

When does Apache Log % d contain?

 

I. symptom:

In the Apache + mod_jk + JBoss environment, the JBoss processing time is always very different from the processing time in Apache log. The JBoss time is the time from request entry to request end recorded by the framework, for a specific URL, the time is basically within ms, but the % d output from Apache log is mostly over ms, and some are surprisingly several hundred seconds.

 

Ii. Purpose:

Find out the time difference between JBoss's business processing and Apache log processing. If a normal business logic processing takes only 100 ms, but it costs 200 ms because Apache is used.

The architecture is faulty, which wastes more than one time.

 

Iii. Analysis:

It was initially suspected that the communication between mod_jk and JBoss was caused, but after the test, it was found that Apache did not load JK's own static resources for a long time sometimes inexplicably.

It is suspected that the loaded module consumes time, but the phenomenon still exists when all modules are dropped.

 

For more information, see the following sentence: the time taken to serve the request, in microseconds. It indicates that the time of % d is "server processing time ".

Then, you can search for relevant information online and find an article (not specific to the name). The conclusion does not include the time when the request was sent.

 

The time for the server to process the request should be the time before all requests are accepted and then ready for processing to send the response. It is impossible to read a static resource.

The number of seconds. Even if the file is not cached in the memory, read the file from the disk and then output the file. This time is too far from the % d log.

 

The only universal key to solve the problem is the source code. Read ...................................

 

Find mod_log_config.c:

 

Static const char * log_request_duration (request_rec * r, char * A) <br/>{< br/> apr_time_t duration = apr_time_now ()-R-> request_time; <br/> return apr_psprintf (R-> pool, "%" apr_time_t_fmt, apr_time_sec (duration )); <br/>}< br/> static const char * log_request_duration_microseconds (request_rec * r, char * A) <br/>{< br/> return apr_psprintf (R-> pool, "%" apr_time_t_fmt, <br/> (apr_time_now ()-R-> request_time); <br/>}< br/>

 

Apr_time_now () is not in doubt. The end of the server logic processing does not include the time when the response content is sent to the client.

So when does R-> request_time start?

 

Locate protocol. C and find:

Static int read_request_line (request_rec * r, apr_bucket_brigade * bb) <br/>{< br/> const char * ll; <br/> const char * URI; <br/> const char * pro; <br/> # If 0 <br/> conn_rec * conn = r-> connection; <br/> # endif <br/> int major = 1, minor = 0; /* assume HTTP/1.0 if non-"HTTP" Protocol */<br/> char HTTP [5]; <br/> apr_size_t Len; <br/> int num_blank_lines = 0; <br/> int max_blank_lines = r-> server-> limit_r Eq_fields; <br/> If (max_blk_lines <= 0) {<br/> max_blk_lines = default_limit_request_fields; <br/>}< br/>/* read past empty lines until we get a real request line, <br/> * A read error, the connection closes (EOF ), or we timeout. <br/> * we skip empty lines because browsers have to tack a CRLF on to the end <br/> * of posts to support old CERN webservers. but note that we may not <B R/> * have flushed any previous response completely to the client yet. <br/> * we delay the flush as long as possible so that we can improve <br/> * performance for clients that are pipelining requests. if a request <br/> * Is pipelined then we won't block during the (implicit) read () below. <br/> * If the requests aren't pipelined, then the client is still waiting <br/> * for the final buffer fl Ush from us, and we will block in the implicit <br/> * read (). B _saferead ensures that the buff layer flushes if it will <br/> * have to block during a read. <br/> */<br/> do {<br/> apr_status_t RV; <br/>/* insure ap_rgetline allocates memory each time thru the loop <br/> * if there are empty lines <br/> */<br/> r-> the_request = NULL; <br/> Rv = ap_rgetline (& (R-> the_request), (apr_size_t) (R-> S Erver-> limit_req_line + 2), <br/> & Len, R, 0, BB); <br/> If (RV! = Apr_success) {<br/> r-> request_time = apr_time_now (); <br/>/* ap_rgetline returns apr_enospc if it fills up the <br/> * buffer before finding the end-of-line. this is only going to <br/> * happen if it exceeds the configured limit for a request-line. <br/> */<br/> If (Rv = apr_enospc) {<br/> r-> Status = http_request_uri_too_large; <br/> r-> proto_num = http_version (1.0); <br/> r-> protocol = apr_pstrdup (R-> pool, "HTTP "); <br/>}< br/> return 0; <br/>}< br/>}while (LEN <= 0) & (++ num_blk_lines <max_blk_lines); <br/>/* We 've probably got something to do, ignore Graceful Restart requests */<br/> r-> request_time = apr_time_now (); <br/> LL = r-> the_request; <br/> r-> method = ap_getword_white (R-> pool, & LL ); <br/> # If 0 <br/>/* XXX if we want to keep track of the method, the protocol module shoshould DO <br/> * It. that support isn' t in the scoreboard yet. hopefully next week <br/> * sometime. RBB */<br/> ap_update_connection_status (ap_child_thread_from_id (Conn-> ID), "method", <br/> r-> method ); <br/> # endif <br/> uri = ap_getword_white (R-> pool, & LL ); <br/>/* provide quick information about the request method as soon as known */<br/> r-> method_number = ap_method_number_of (R-> method ); <br/> If (R-> method_number = m_get & R-> method [0] = 'H') {<br/> r-> header_only = 1; <br/>}< br/> ap_parse_uri (R, Uri); <br/> If (LL [0]) {<br/> r-> assbackwards = 0; <br/> pro = ll; <br/> Len = strlen (LL); <br/>}else {<br/> r-> assbackwards = 1; <br/> pro = "HTTP/0.9"; <br/> Len = 8; <br/>}< br/> r-> protocol = apr_pstrmemdup (R-> pool, Pro, Len); <br/>/* XXX ap_update_connection_status (Conn-> ID, "protocol", R-> Protocol ); */<br/>/* avoid sscanf in the common case */<br/> If (LEN = 8 <br/> & Pro [0] = 'H '& Pro [1] = 'T' & Pro [2] = 'T' & Pro [3] = 'P' <br/> && pro [4] = '/' & apr_isdigit (PRO [5]) & Pro [6] = '. '<br/> & apr_isdigit (PRO [7]) {<br/> r-> proto_num = http_version (PRO [5]-'0 ', pro [7]-'0'); <br/>}< br/> else if (3 = sscanf (R-> protocol, "% 4 S/% u. % u ", HTTP, & major, & minor) <br/> & (strcasecmp (" HTTP ", HTTP) = 0) <br/> & (minor <pttp_version (1, 0 ))) /* don't allow HTTP/0.1000 */<br/> r-> proto_num = http_version (Major, minor ); <br/> else <br/> r-> proto_num = http_version (1, 0); <br/> return 1; <br/>}

 

This time starts timing after the first line of the request is analyzed (read). Note that no matter whether the first line is valid or not, it will assign a value to R-> request_time.

If (RV! = Apr_success ){
R-> request_time = apr_time_now ();

......

Return 0;

}

...........

R-> request_time = apr_time_now ();

 

Therefore, % d actually contains the time when most requests are sent. Most of them mean that the network transmission time before the first row is read is excluded, but if the first row is read, for example, if you have read the "get/path HTTP/1.1/R/N" content and the following content is in poor network conditions during transmission, the transmission time will be included.

 

Iv. Verification:

 

Write a socket to communicate with Apache, test a normal connection time, and test on the local machine to minimize network latency.

Socket SC = new socket ("127.0.0.1", 9000); <br/> printwriter out = new printwriter (New outputstreamwriter (SC. getoutputstream (); <br/> out. print ("Get/testweb/thirdservlet? Test = 1111 HTTP/1.1/R/N "); <br/> out. print ("accept: image/JPEG, application/X-MS-application, image/GIF, application/XAML + XML, image/pjpeg, application/X-MS-xbap, application/vnd. MS-Excel, application/vnd. MS-PowerPoint, application/MSWord, application/X-Shockwave-flash, */* r/RN "); <br/> out. print ("Accept-encoding: gzip, Deflater/R/N"); <br/> out. print ("Accept-language: ZH-CN/R/N"); <br/> out. print ("Conn Ection: Close/R/N "); <br/> out. print ("Host: 10.16.26.81: 9000/R/N"); <br/> out. print ("User-Agent: Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; Trident/4.0; Embedded Web browser from: http://bsalsa.com/; slcc2 ;. net CLR 2.0.50727 ;. net CLR 3.5.30729 ;. net CLR 3.0.30729; Media Center PC 6.0; infopath.3 ;. net4.0c ;. net4.0e; MSN optimizedie8; zhcn)/R/n/R/N "); <br/> out. flush (); <br/> inputstream in = SC. getinputstream (); <br/> byte [] Buf = new byte [1024]; <br/> int Len; <br/> while (LEN = in. read (BUF ))! =-1) {<br/> system. out. print (new string (BUF, 0, Len); <br/>}< br/> system. out. println (); <br/> in. close (); <br/> out. close (); <br/> SC. close (); <br/> system. out. println (I); <br/>

 

This code loops 100 times. Apache log's % d time is around 340 μs, and JBoss's time is around 300 μs. This code runs on the client at around 550 μs. Note that this time is the unit of μs.

Modify the code above:

Socket SC = new socket ("127.0.0.1", 9000); <br/> printwriter out = new printwriter (New outputstreamwriter (SC. getoutputstream (); <br/> out. print ("Get/testweb/Third"); <br/> out. flush (); <br/> thread. sleep (100); <br/> out. print ("Servlet? Test = 1111 HTTP/1.1/R/N "); <br/> out. print ("accept: image/JPEG, application/X-MS-application, image/GIF, application/XAML + XML, image/pjpeg, application/X-MS-xbap, application/vnd. MS-Excel, application/vnd. MS-PowerPoint, application/MSWord, application/X-Shockwave-flash, */* r/RN "); <br/> out. print ("Accept-encoding: gzip, Deflater/R/N"); <br/> out. print ("Accept-language: ZH-CN/R/N"); <br/> out. print ("Conn Ection: Close/R/N "); <br/> out. print ("Host: 10.16.26.81: 9000/R/N"); <br/> out. print ("User-Agent: Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; Trident/4.0; Embedded Web browser from: http://bsalsa.com/; slcc2 ;. net CLR 2.0.50727 ;. net CLR 3.5.30729 ;. net CLR 3.0.30729; Media Center PC 6.0; infopath.3 ;. net4.0c ;. net4.0e; MSN optimizedie8; zhcn)/R/n/R/N "); <br/> out. flush (); <br/> inputstream in = SC. getinputstream (); <br/> byte [] Buf = new byte [1024]; <br/> int Len; <br/> while (LEN = in. read (BUF ))! =-1) {<br/> system. out. print (new string (BUF, 0, Len); <br/>}< br/> system. out. println (); <br/> in. close (); <br/> out. close (); <br/> SC. close (); <br/> system. out. println (I); <br/>

Alternatively, after the socket is established, place sleep in the first line after the out is created to simulate the network latency before the first line is read by the server, the result is basically the same as the first normal condition of the network. Except for the normal fluctuations in each request, the average value is almost unchanged.

 

Modify the code again:

Socket SC = new socket ("127.0.0.1", 9000); <br/> printwriter out = new printwriter (New outputstreamwriter (SC. getoutputstream (); <br/> out. print ("Get/testweb/thirdservlet? Test = 1111 HTTP/1.1/R/N "); <br/> out. flush (); <br/> thread. sleep (100); <br/> out. print ("accept: image/JPEG, application/X-MS-application, image/GIF, application/XAML + XML, image/pjpeg, application/X-MS-xbap, application/vnd. MS-Excel, application/vnd. MS-PowerPoint, application/MSWord, application/X-Shockwave-flash, */* r/RN "); <br/> out. print ("Accept-encoding: gzip, Deflater/R/N"); <br/> out. print ("Accept-l Anguage: ZH-CN/R/N "); <br/> out. print ("connection: Close/R/N"); <br/> out. print ("Host: 10.16.26.81: 9000/R/N"); <br/> out. print ("User-Agent: Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; Trident/4.0; Embedded Web browser from: http://bsalsa.com/; slcc2 ;. net CLR 2.0.50727 ;. net CLR 3.5.30729 ;. net CLR 3.0.30729; Media Center PC 6.0; infopath.3 ;. net4.0c ;. net4.0e; MSN optimizedie8; zhcn)/R/n/R/N "); <Br/> out. flush (); <br/> inputstream in = SC. getinputstream (); <br/> byte [] Buf = new byte [1024]; <br/> int Len; <br/> while (LEN = in. read (BUF ))! =-1) {<br/> system. out. print (new string (BUF, 0, Len); <br/>}< br/> system. out. println (); <br/> in. close (); <br/> out. close (); <br/> SC. close (); <br/> system. out. println (I); <br/>

Place sleep between any row after the first domain is sent. The time difference is obvious. Because the time units for processing 340 on the server and running on the client are both μs, and the sleep time here is ms, the obvious difference is immediately displayed on the server, JBoss's business processing time has not changed, but Apache Log % d suddenly becomes around 100700 μs, except for the 100000 μs transmitted by the client network, the "other" time is doubled, which means the latency is amplified. When the network latency is reached, the overhead of switching between the waiting network data and other logic of the thread processing the request increases. Based on the same principle, the average running time of the client is about 101200 μs, And the 100000 μs of sleep is removed, because the thread function of sleep itself consumes a lot of time.

 

 

V. Conclusion: Apache Log % d indicates the server processing time, but it actually contains all client transmission time except the network transmission time before the first domain. This statement is very easy. To put it bluntly, it means that the time starts after the first line of the original domain is read, including the whole server processing time including the network transmission time of the Request's subsequent content.