You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by Jim Jagielski <ji...@jaguNET.com> on 1997/07/05 02:15:02 UTC
[PATCH] Take III, final version of request-time
Aha... I was wondering why my servers were showing almost no time
at all when processing requests... Seems that process_request()
would set the child status to BUSY_LOG and then back again to
BUSY_WRITE. Well, the code triggers on BUSY_WRITE as the start of
the request... To fix, I added another child stage, DONE_REQ which
is basically set when the child is done processing the request.
Enjoy:
Index: apache/src/PORTING
===================================================================
RCS file: /export/home/cvs/apache/src/PORTING,v
retrieving revision 1.6
diff -c -r1.6 PORTING
*** PORTING 1997/06/30 21:42:31 1.6
--- PORTING 1997/07/05 00:08:11
***************
*** 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:
Index: apache/src/conf.h
===================================================================
RCS file: /export/home/cvs/apache/src/conf.h,v
retrieving revision 1.110
diff -c -r1.110 conf.h
*** conf.h 1997/07/02 03:38:30 1.110
--- conf.h 1997/07/05 00:08:12
***************
*** 74,79 ****
--- 74,80 ----
extern void GETUSERMODE();
extern char *inet_ntoa();
#define NO_SLACK
+ #define NO_GETTIMEOFDAY
#elif defined(SUNOS4)
#define HAVE_GMTOFF
Index: apache/src/http_main.c
===================================================================
RCS file: /export/home/cvs/apache/src/http_main.c,v
retrieving revision 1.173
diff -c -r1.173 http_main.c
*** http_main.c 1997/07/02 04:09:06 1.173
--- http_main.c 1997/07/05 00:08:14
***************
*** 1088,1093 ****
--- 1088,1096 ----
{
int old_status;
short_score new_score_rec;
+ #if defined(STATUS) && defined(NO_GETTIMEOFDAY)
+ struct tms tms_blk;
+ #endif
if (child_num < 0)
return -1;
***************
*** 1111,1116 ****
--- 1114,1142 ----
new_score_rec.conn_count = (unsigned short)0;
new_score_rec.conn_bytes = (unsigned long)0;
}
+ else if (status == SERVER_BUSY_WRITE) {
+ #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 == SERVER_DONE_REQ) {
+ #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
+
+ }
if (r) {
int slot_size;
conn_rec *c = r->connection;
***************
*** 1156,1164 ****
--- 1182,1192 ----
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
--- 1194,1199 ----
***************
*** 2241,2247 ****
#if defined(STATUS)
increment_counts(child_num, r);
#endif
! if (!current_conn->keepalive || current_conn->aborted)
break;
destroy_pool(r->pool);
--- 2267,2273 ----
#if defined(STATUS)
increment_counts(child_num, r);
#endif
! if (!current_conn->keepalive || current_conn->aborted)
break;
destroy_pool(r->pool);
Index: apache/src/http_request.c
===================================================================
RCS file: /export/home/cvs/apache/src/http_request.c,v
retrieving revision 1.56
diff -c -r1.56 http_request.c
*** http_request.c 1997/07/01 06:46:02 1.56
--- http_request.c 1997/07/05 00:08:15
***************
*** 1031,1047 ****
void process_request (request_rec *r)
{
- #ifdef STATUS
- int old_stat;
- #endif /* STATUS */
process_request_internal (r);
#ifdef STATUS
! old_stat = update_child_status (r->connection->child_num, SERVER_BUSY_LOG,
! r);
#endif /* STATUS */
log_transaction (r);
#ifdef STATUS
! (void)update_child_status (r->connection->child_num, old_stat, r);
#endif /* STATUS */
}
--- 1031,1043 ----
void process_request (request_rec *r)
{
process_request_internal (r);
#ifdef STATUS
! (void)update_child_status (r->connection->child_num, SERVER_BUSY_LOG, r);
#endif /* STATUS */
log_transaction (r);
#ifdef STATUS
! (void)update_child_status (r->connection->child_num, SERVER_DONE_REQ, r);
#endif /* STATUS */
}
Index: apache/src/mod_status.c
===================================================================
RCS file: /export/home/cvs/apache/src/mod_status.c,v
retrieving revision 1.49
diff -c -r1.49 mod_status.c
*** mod_status.c 1997/07/03 21:27:23 1.49
--- mod_status.c 1997/07/05 00:08:16
***************
*** 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
***************
*** 229,234 ****
--- 230,236 ----
status[SERVER_BUSY_LOG]='L';
status[SERVER_BUSY_DNS]='D';
status[SERVER_GRACEFUL]='G';
+ status[SERVER_DONE_REQ]='F';
if (!exists_scoreboard_image()) {
log_printf(r->server, "Server status unavailable in inetd mode");
***************
*** 286,295 ****
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;
--- 288,294 ----
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;
***************
*** 414,419 ****
--- 413,419 ----
rputs("\"<B><code>S</code></B>\" Starting up, \n",r);
rputs("\"<B><code>R</code></B>\" Reading Request,<BR>\n",r);
rputs("\"<B><code>W</code></B>\" Sending Reply, \n",r);
+ rputs("\"<B><code>F</code></B>\" Finishing Reply, \n",r);
rputs("\"<B><code>K</code></B>\" Keepalive (read), \n",r);
rputs("\"<B><code>D</code></B>\" DNS Lookup,<BR>\n",r);
rputs("\"<B><code>L</code></B>\" Logging, \n",r);
***************
*** 428,442 ****
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;
--- 428,462 ----
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;
***************
*** 486,507 ****
case SERVER_GRACEFUL:
rputs("Graceful",r);
break;
default:
rputs("?STATE?",r);
break;
}
#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);
--- 506,531 ----
case SERVER_GRACEFUL:
rputs("Graceful",r);
break;
+ case SERVER_DONE_REQ:
+ rputs("<b>Finishing</b>",r);
+ break;
default:
rputs("?STATE?",r);
break;
}
#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);
***************
*** 550,570 ****
case SERVER_GRACEFUL:
rputs("<td>G",r);
break;
default:
rputs("<td>?",r);
break;
}
#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,598 ----
case SERVER_GRACEFUL:
rputs("<td>G",r);
break;
+ case SERVER_DONE_REQ:
+ rputs("<td><b>F</b>",r);
+ break;
default:
rputs("<td>?",r);
break;
}
#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);
***************
*** 587,592 ****
--- 615,621 ----
<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 \
***************
*** 601,606 ****
--- 630,636 ----
<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 \
Index: apache/src/mod_usertrack.c
===================================================================
RCS file: /export/home/cvs/apache/src/mod_usertrack.c,v
retrieving revision 1.10
diff -c -r1.10 mod_usertrack.c
*** mod_usertrack.c 1997/03/07 14:15:45 1.10
--- mod_usertrack.c 1997/07/05 00:08:16
***************
*** 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. */
Index: apache/src/scoreboard.h
===================================================================
RCS file: /export/home/cvs/apache/src/scoreboard.h,v
retrieving revision 1.23
diff -c -r1.23 scoreboard.h
*** scoreboard.h 1997/06/24 00:32:32 1.23
--- scoreboard.h 1997/07/05 00:08:16
***************
*** 74,79 ****
--- 74,80 ----
#define SERVER_BUSY_LOG 6 /* Logging the request */
#define SERVER_BUSY_DNS 7 /* Looking up a hostname */
#define SERVER_GRACEFUL 8 /* server is gracefully finishing request */
+ #define SERVER_DONE_REQ 9 /* Server is done processing request */
typedef struct {
pid_t pid;
***************
*** 85,90 ****
--- 86,98 ----
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... */
--
====================================================================
Jim Jagielski | jaguNET Access Services
jim@jaguNET.com | http://www.jaguNET.com/
"Look at me! I'm wearing a cardboard belt!"
Re: [PATCH] Take III, final version of request-time
Posted by Dean Gaudet <dg...@arctic.org>.
+1 in principle.
I managed to do something like this in hotwired's code just by mimicing
the setting of r->request_time. However I chose to move it up to the
connection record ('cause I never feel confident about getting all the
sub request cases properly :). Then a special module logs the data... to
get a good wall-clock rating I chose to call the times logger specially
in the child_main loop *after* the socket had been closed. This gets
closer to what the end-user experienced for real-time download time.
The difference in the approaches (other than the use of the data) is that
with yours it requires a little more knowledge of how the core code changes
the child status. Whereas if you do it right in child_main (or a related
routine) it might be less likely to break in the future.
Dean
On Fri, 4 Jul 1997, Jim Jagielski wrote:
> Aha... I was wondering why my servers were showing almost no time
> at all when processing requests... Seems that process_request()
> would set the child status to BUSY_LOG and then back again to
> BUSY_WRITE. Well, the code triggers on BUSY_WRITE as the start of
> the request... To fix, I added another child stage, DONE_REQ which
> is basically set when the child is done processing the request.