jim 97/07/07 07:34:34
Modified: src CHANGES PORTING conf.h http_main.c http_main.h http_request.c mod_status.c mod_usertrack.c scoreboard.h Log: Determine and display the time required to process a request for the status module Revision Changes Path 1.324 +4 -0 apache/src/CHANGES Index: CHANGES =================================================================== RCS file: /export/home/cvs/apache/src/CHANGES,v retrieving revision 1.323 retrieving revision 1.324 diff -C3 -r1.323 -r1.324 *** CHANGES 1997/07/06 05:37:18 1.323 --- CHANGES 1997/07/07 14:34:24 1.324 *************** *** 1,4 **** --- 1,8 ---- Changes with Apache 1.3 + + *) We now determine and display the time spent processing a + request if desired. + *) CGI: Add a select() loop so that CGI scripts don't have to be nph in order to be "unbuffered". [Sameer Parekh] 1.7 +3 -0 apache/src/PORTING Index: PORTING =================================================================== RCS file: /export/home/cvs/apache/src/PORTING,v retrieving revision 1.6 retrieving revision 1.7 diff -C3 -r1.6 -r1.7 *** PORTING 1997/06/30 21:42:31 1.6 --- PORTING 1997/07/07 14:34:24 1.7 *************** *** 230,235 **** --- 230,238 ---- NO_SLACK: Do not use the "slack" fd feature which requires a working fcntl F_DUPFD. + NO_GETTIMEOFDAY: + OS does not have the gettimeofday() function (which is + BSDish). This assumes it has times() instead. -- MISC #DEFINES: 1.111 +1 -0 apache/src/conf.h Index: conf.h =================================================================== RCS file: /export/home/cvs/apache/src/conf.h,v retrieving revision 1.110 retrieving revision 1.111 diff -C3 -r1.110 -r1.111 *** conf.h 1997/07/02 03:38:30 1.110 --- conf.h 1997/07/07 14:34:25 1.111 *************** *** 74,79 **** --- 74,80 ---- extern void GETUSERMODE(); extern char *inet_ntoa(); #define NO_SLACK + #define NO_GETTIMEOFDAY #elif defined(SUNOS4) #define HAVE_GMTOFF 1.174 +48 -3 apache/src/http_main.c Index: http_main.c =================================================================== RCS file: /export/home/cvs/apache/src/http_main.c,v retrieving revision 1.173 retrieving revision 1.174 diff -C3 -r1.173 -r1.174 *** http_main.c 1997/07/02 04:09:06 1.173 --- http_main.c 1997/07/07 14:34:26 1.174 *************** *** 1149,1154 **** --- 1149,1195 ---- } #if defined(STATUS) + void time_process_request (int child_num, int status) + { + short_score new_score_rec; + #if defined(NO_GETTIMEOFDAY) + struct tms tms_blk; + #endif + + if (child_num < 0) + return ; + + sync_scoreboard_image(); + new_score_rec = scoreboard_image->servers[child_num]; + + if (status == START_PREQUEST) { + #if defined(NO_GETTIMEOFDAY) + if ((new_score_rec.start_time = times(&tms_blk)) == -1) + new_score_rec.start_time = (clock_t)0; + #else + if (gettimeofday(&new_score_rec.start_time, (struct timezone *)0) < 0) + new_score_rec.start_time.tv_sec = + new_score_rec.start_time.tv_usec = 0L; + #endif + } + else if (status == STOP_PREQUEST) { + #if defined(NO_GETTIMEOFDAY) + if ((new_score_rec.stop_time = times(&tms_blk)) == -1) + new_score_rec.stop_time = new_score_rec.start_time = (clock_t)0; + #else + if (gettimeofday(&new_score_rec.stop_time, (struct timezone *)0) < 0) + new_score_rec.stop_time.tv_sec = + new_score_rec.stop_time.tv_usec = + new_score_rec.start_time.tv_sec = + new_score_rec.start_time.tv_usec = 0L; + #endif + + } + + put_scoreboard_info(child_num, &new_score_rec); + + } + static void increment_counts (int child_num, request_rec *r) { long int bs=0; *************** *** 1156,1164 **** --- 1197,1207 ---- sync_scoreboard_image(); new_score_rec = scoreboard_image->servers[child_num]; + if (r->sent_bodyct) bgetopt(r->connection->client, BO_BYTECT, &bs); + times(&new_score_rec.times); new_score_rec.access_count ++; new_score_rec.my_access_count ++; new_score_rec.conn_count ++; *************** *** 1166,1173 **** new_score_rec.my_bytes_served += (unsigned long)bs; new_score_rec.conn_bytes += (unsigned long)bs; - times(&new_score_rec.times); - put_scoreboard_info(child_num, &new_score_rec); } #endif --- 1209,1214 ---- *************** *** 2238,2247 **** (void)update_child_status(child_num, SERVER_BUSY_WRITE, r); process_request(r); #if defined(STATUS) increment_counts(child_num, r); #endif ! if (!current_conn->keepalive || current_conn->aborted) break; destroy_pool(r->pool); --- 2279,2290 ---- (void)update_child_status(child_num, SERVER_BUSY_WRITE, r); process_request(r); + #if defined(STATUS) increment_counts(child_num, r); #endif ! ! if (!current_conn->keepalive || current_conn->aborted) break; destroy_pool(r->pool); *************** *** 2981,2989 **** --- 3024,3034 ---- (void)update_child_status(child_num, SERVER_BUSY_WRITE, r); process_request(r); + #if defined(STATUS) increment_counts(child_num, r); #endif + if (!current_conn->keepalive || current_conn->aborted) break; 1.13 +1 -0 apache/src/http_main.h Index: http_main.h =================================================================== RCS file: /export/home/cvs/apache/src/http_main.h,v retrieving revision 1.12 retrieving revision 1.13 diff -C3 -r1.12 -r1.13 *** http_main.h 1997/06/30 21:10:01 1.12 --- http_main.h 1997/07/07 14:34:27 1.13 *************** *** 93,97 **** --- 93,98 ---- void sync_scoreboard_image (); int update_child_status (int child_num, int status, request_rec *r); + void time_process_request (int child_num, int status); unsigned int set_callback_and_alarm(void (*fn)(int), int x); int check_alarm(); 1.57 +3 -0 apache/src/http_request.c Index: http_request.c =================================================================== RCS file: /export/home/cvs/apache/src/http_request.c,v retrieving revision 1.56 retrieving revision 1.57 diff -C3 -r1.56 -r1.57 *** http_request.c 1997/07/01 06:46:02 1.56 --- http_request.c 1997/07/07 14:34:27 1.57 *************** *** 1033,1038 **** --- 1033,1040 ---- { #ifdef STATUS int old_stat; + + time_process_request(r->connection->child_num, START_PREQUEST); #endif /* STATUS */ process_request_internal (r); #ifdef STATUS *************** *** 1042,1047 **** --- 1044,1050 ---- log_transaction (r); #ifdef STATUS (void)update_child_status (r->connection->child_num, old_stat, r); + time_process_request(r->connection->child_num, STOP_PREQUEST); #endif /* STATUS */ } 1.51 +34 -12 apache/src/mod_status.c Index: mod_status.c =================================================================== RCS file: /export/home/cvs/apache/src/mod_status.c,v retrieving revision 1.50 retrieving revision 1.51 diff -C3 -r1.50 -r1.51 *** mod_status.c 1997/07/05 17:42:39 1.50 --- mod_status.c 1997/07/07 14:34:28 1.51 *************** *** 204,209 **** --- 204,210 ---- unsigned short conn_lres; unsigned long bcount=0; unsigned long kbcount=0; + long req_time; #ifdef NEXT float tick=HZ; #else *************** *** 285,294 **** stat_buffer[i] = status[res]; if (res == SERVER_READY) ready++; ! else if (res == SERVER_BUSY_READ || res==SERVER_BUSY_WRITE || ! res == SERVER_STARTING || res==SERVER_BUSY_KEEPALIVE || ! res == SERVER_BUSY_LOG || res==SERVER_BUSY_DNS || ! res == SERVER_GRACEFUL) busy++; #if defined(STATUS) lres = score_record.access_count; --- 286,292 ---- stat_buffer[i] = status[res]; if (res == SERVER_READY) ready++; ! else if (res != SERVER_DEAD && res != SERVER_UNKNOWN) busy++; #if defined(STATUS) lres = score_record.access_count; *************** *** 427,441 **** else #ifdef __EMX__ /* Allow for OS/2 not having CPU stats */ ! rputs("<p>\n\n<table border=0><tr><th>Srv<th>PID<th>Acc<th>M\n<th>SS<th>Conn<th>Child<th>Slot<th>Host<th>VHost<th>Request</tr>\n\n",r); #else ! rputs("<p>\n\n<table border=0><tr><th>Srv<th>PID<th>Acc<th>M<th>CPU\n<th>SS<th>Conn<th>Child<th>Slot<th>Host<th>VHost<th>Request</tr>\n\n",r); #endif for (i = 0; i<HARD_SERVER_LIMIT; ++i) { score_record=get_scoreboard_info(i); lres = score_record.access_count; my_lres = score_record.my_access_count; conn_lres = score_record.conn_count; --- 425,459 ---- else #ifdef __EMX__ /* Allow for OS/2 not having CPU stats */ ! rputs("<p>\n\n<table border=0><tr><th>Srv<th>PID<th>Acc<th>M\n<th>SS<th>Req<th>Conn<th>Child<th>Slot<th>Host<th>VHost<th>Request</tr>\n\n",r); #else ! rputs("<p>\n\n<table border=0><tr><th>Srv<th>PID<th>Acc<th>M<th>CPU\n<th>SS<th>Req<th>Conn<th>Child<th>Slot<th>Host<th>VHost<th>Request</tr>\n\n",r); #endif for (i = 0; i<HARD_SERVER_LIMIT; ++i) { score_record=get_scoreboard_info(i); + + #if defined(NO_GETTIMEOFDAY) + if (score_record.start_time == (clock_t)0) + req_time = 0L; + else { + req_time = score_record.stop_time - score_record.start_time; + req_time = (req_time*1000)/(int)tick; + } + #else + if (score_record.start_time.tv_sec == 0L && + score_record.start_time.tv_usec == 0L) + req_time = 0L; + else + req_time = + ((score_record.stop_time.tv_sec-score_record.start_time.tv_sec)*1000)+ + ((score_record.stop_time.tv_usec-score_record.start_time.tv_usec)/1000); + #endif + if (req_time < 0L) + req_time = 0L; + lres = score_record.access_count; my_lres = score_record.my_access_count; conn_lres = score_record.conn_count; *************** *** 491,506 **** } #ifdef __EMX__ /* Allow for OS/2 not having CPU stats */ ! rprintf(r,"]\n %s (", #else ! rprintf(r,"] u%g s%g cu%g cs%g\n %s (", score_record.times.tms_utime/tick, score_record.times.tms_stime/tick, score_record.times.tms_cutime/tick, score_record.times.tms_cstime/tick, #endif ! asctime(localtime(&score_record.last_used))); format_byte_out(r,conn_bytes); rputs("|",r); format_byte_out(r,my_bytes); --- 509,525 ---- } #ifdef __EMX__ /* Allow for OS/2 not having CPU stats */ ! rprintf(r,"]\n %.0f %ld (", #else ! rprintf(r,"] u%g s%g cu%g cs%g\n %.0f %ld (", score_record.times.tms_utime/tick, score_record.times.tms_stime/tick, score_record.times.tms_cutime/tick, score_record.times.tms_cstime/tick, #endif ! difftime(nowtime, score_record.last_used), ! (long)req_time); format_byte_out(r,conn_bytes); rputs("|",r); format_byte_out(r,my_bytes); *************** *** 555,569 **** } #ifdef __EMX__ /* Allow for OS/2 not having CPU stats */ ! rprintf(r,"\n<td>%.0f", #else ! rprintf(r,"\n<td>%.2f<td>%.0f", (score_record.times.tms_utime + score_record.times.tms_stime + score_record.times.tms_cutime + score_record.times.tms_cstime)/tick, #endif ! difftime(nowtime, score_record.last_used)); rprintf(r,"<td>%-1.1f<td>%-2.2f<td>%-2.2f\n", (float)conn_bytes/KBYTE, (float)my_bytes/MBYTE, (float)bytes/MBYTE); --- 574,589 ---- } #ifdef __EMX__ /* Allow for OS/2 not having CPU stats */ ! rprintf(r,"\n<td>%.0f<td>%ld", #else ! rprintf(r,"\n<td>%.2f<td>%.0f<td>%ld", (score_record.times.tms_utime + score_record.times.tms_stime + score_record.times.tms_cutime + score_record.times.tms_cstime)/tick, #endif ! difftime(nowtime, score_record.last_used), ! (long)req_time); rprintf(r,"<td>%-1.1f<td>%-2.2f<td>%-2.2f\n", (float)conn_bytes/KBYTE, (float)my_bytes/MBYTE, (float)bytes/MBYTE); *************** *** 586,591 **** --- 606,612 ---- <tr><th>Acc<td>Number of accesses this connection / this child / this slot\n \ <tr><th>M<td>Mode of operation\n \ <tr><th>SS<td>Seconds since beginning of most recent request\n \ + <tr><th>Req<td>Milliseconds required to process most recent request\n \ <tr><th>Conn<td>Kilobytes transferred this connection\n \ <tr><th>Child<td>Megabytes transferred this child\n \ <tr><th>Slot<td>Total megabytes transferred this slot\n \ *************** *** 600,605 **** --- 621,627 ---- <tr><th>M<td>Mode of operation\n \ <tr><th>CPU<td>CPU usage, number of seconds\n \ <tr><th>SS<td>Seconds since beginning of most recent request\n \ + <tr><th>Req<td>Milliseconds required to process most recent request\n \ <tr><th>Conn<td>Kilobytes transferred this connection\n \ <tr><th>Child<td>Megabytes transferred this child\n \ <tr><th>Slot<td>Total megabytes transferred this slot\n \ 1.11 +3 -3 apache/src/mod_usertrack.c Index: mod_usertrack.c =================================================================== RCS file: /export/home/cvs/apache/src/mod_usertrack.c,v retrieving revision 1.10 retrieving revision 1.11 diff -C3 -r1.10 -r1.11 *** mod_usertrack.c 1997/03/07 14:15:45 1.10 --- mod_usertrack.c 1997/07/07 14:34:28 1.11 *************** *** 120,126 **** { cookie_log_state *cls = get_module_config (r->server->module_config, &usertrack_module); ! #ifdef MPE clock_t mpe_times; struct tms mpe_tms; #else --- 120,126 ---- { cookie_log_state *cls = get_module_config (r->server->module_config, &usertrack_module); ! #if defined(NO_GETTIMEOFDAY) clock_t mpe_times; struct tms mpe_tms; #else *************** *** 137,144 **** if ((dot = strchr(rname,'.'))) *dot='\0'; /* First bit of hostname */ ! #ifdef MPE ! /* MPE lacks gettimeofday(), so we must use time() to obtain the epoch seconds, and then times() to obtain CPU clock ticks (milliseconds). Combine this together to obtain a hopefully unique cookie ID. */ --- 137,144 ---- if ((dot = strchr(rname,'.'))) *dot='\0'; /* First bit of hostname */ ! #if defined(NO_GETTIMEOFDAY) ! /* We lack gettimeofday(), so we must use time() to obtain the epoch seconds, and then times() to obtain CPU clock ticks (milliseconds). Combine this together to obtain a hopefully unique cookie ID. */ 1.24 +11 -0 apache/src/scoreboard.h Index: scoreboard.h =================================================================== RCS file: /export/home/cvs/apache/src/scoreboard.h,v retrieving revision 1.23 retrieving revision 1.24 diff -C3 -r1.23 -r1.24 *** scoreboard.h 1997/06/24 00:32:32 1.23 --- scoreboard.h 1997/07/07 14:34:28 1.24 *************** *** 85,90 **** --- 85,97 ---- unsigned long my_bytes_served; unsigned long conn_bytes; unsigned short conn_count; + #if defined(NO_GETTIMEOFDAY) + clock_t start_time; + clock_t stop_time; + #else + struct timeval start_time; + struct timeval stop_time; + #endif struct tms times; time_t last_used; char client[32]; /* Keep 'em small... */ *************** *** 110,112 **** --- 117,123 ---- extern void sync_scoreboard_image(void); short_score get_scoreboard_info(int x); int exists_scoreboard_image (); + + /* for time_process_request() in http_main.c */ + #define START_PREQUEST 1 + #define STOP_PREQUEST 2