I repeatedly inserted millisecond or microsecond timestamps as well as
PID and thread ID information into the ErrorLog when trying to diagnose
problems, most often in combination with additional log lines.
Due to the increased load and capability of systems and increasing
amount of concurrency, would those features be interesting by default?
1) Sub-second timestamps in error log
Index: server/util_time.c
===================================================================
--- server/util_time.c (revision 949733)
+++ server/util_time.c (working copy)
@@ -151,6 +151,8 @@
apr_time_exp_t xt;
const char *s;
int real_year;
+ int usec;
+ int div;
/* example: "Wed Jun 30 21:49:08 1993" */
/* 123456789012345678901234 */
@@ -177,6 +179,12 @@
*date_str++ = ':';
*date_str++ = xt.tm_sec / 10 + '0';
*date_str++ = xt.tm_sec % 10 + '0';
+ *date_str++ = '.';
+ usec = (int)xt.tm_usec;
+ for (div=100000; div>0; div=div/10) {
+ *date_str++ = usec / div + '0';
+ usec = usec % div;
+ }
*date_str++ = ' ';
real_year = 1900 + xt.tm_year;
*date_str++ = real_year / 1000 + '0';
Index: server/log.c
===================================================================
--- server/log.c (revision 949733)
+++ server/log.c (working copy)
@@ -594,9 +594,9 @@
if (logf && ((level & APLOG_STARTUP) != APLOG_STARTUP)) {
errstr[0] = '[';
ap_recent_ctime(errstr + 1, apr_time_now());
- errstr[1 + APR_CTIME_LEN - 1] = ']';
- errstr[1 + APR_CTIME_LEN ] = ' ';
- len = 1 + APR_CTIME_LEN + 1;
+ errstr[1 + APR_CTIME_LEN + 7 - 1] = ']';
+ errstr[1 + APR_CTIME_LEN + 7 ] = ' ';
+ len = 1 + APR_CTIME_LEN + 7 + 1;
} else {
len = 0;
}
and maybe switching away from the CTIME name, because it's no longer
real ctime.
2) PID and thread ID
Index: server/log.c
===================================================================
--- server/log.c (revision 949733)
+++ server/log.c (working copy)
@@ -25,6 +25,7 @@
#include "apr_general.h" /* for signal stuff */
#include "apr_strings.h"
#include "apr_errno.h"
+#include "apr_portable.h"
#include "apr_thread_proc.h"
#include "apr_lib.h"
#include "apr_signal.h"
@@ -606,6 +607,18 @@
"[%s] ", priorities[level_and_mask].t_name);
}
+ len += apr_snprintf(errstr + len, MAX_STRING_LEN - len,
+ "[%" APR_PID_T_FMT, getpid());
+#if APR_HAS_THREADS
+ {
+ apr_os_thread_t tid = apr_os_thread_current();
+ len += apr_snprintf(errstr + len, MAX_STRING_LEN - len,
+ ":%pT", &tid);
+ }
+#endif
+ errstr[len++] = ']';
+ errstr[len++] = ' ';
+
if (file && level_and_mask == APLOG_DEBUG) {
#if defined(_OSD_POSIX) || defined(WIN32) || defined(__MVS__)
char tmp[256];
PID and thread id are useful, because the can be correlated with the
access_log (when added there). they also help to understand, which
messages belong "together" when multiple log events are intertwined.
3) Related things for access log
There's a related open Bugzilla about adding sub-second timestamps (not:
duration) to the access log (BZ 49251). The OP suggests to use %M for an
absolute timestamp. It would be nice to improve the strftime use of
%{format}t to allow for a proprietary microsecond letter which will add
the microsecond part of the actual time. I found no standards defined
for that.
4) General correlation improvements
To be able to correlate error and access log, it would be helpful to
share a common id, e.g. the unique_id, and be able to log it in both
files. The id generated by mod_unique_id comes too late though
(post_read_request). Since it actually only uses the request timestamp
and the connection id of the request, it could be calculated much earlier.
Regards,
Rainer
