Hi,
Your patch looks correct. I have only two minor comments:
1. The use of the __WIN__ macro is not common i Falcon. I think we
mostly use something else for determining Windows code (_WIN32?)
2. You allocate 256 bytes for the string. In most cases this will be
more than enough but will there be cases where this will truncate the
output?
Running with this patch produces the following output:
081007 03:31:12 Falcon: Serial log write took 2 seconds
081007 03:34:35 Falcon: Serial log write took 2 seconds
081007 03:36:16 Falcon: Serial log write took 2 seconds
which looks very good.
It also produces the following output for "multi-line" debug output:
081007 03:24:56 Falcon: ------------------------------------
081007 03:25:45 Falcon: Record Memory usage for FALCON_MASTER:
081007 03:25:55 Falcon: Stalled threads
081007 03:25:55 Falcon: Thread 101819d30 (22) sleep=0, grant=0,
locks=1, who 0, parent=0
081007 03:25:55 Falcon: Pending Table::insert state 0 (1) syncObject
1017430c0
081007 03:25:55 Falcon: Stalled synchronization objects:
081007 03:25:55 Falcon: SyncObject 1017430c0: state 1, readers 0,
monitor 0, waiters 1
081007 03:25:55 Falcon: Waiting thread 1819d30 (22), type 1;
Table::insert
081007 03:25:55 Falcon: ------------------------------------
which looks a bit more "too verbose" but I think it is better to have
the time stamp on all of these than skipping some of them.
Thanks for making this patch.
OK to push (but check with some of our Windows champions about the use
of the __WIN__ macro).
Olav
Lars-Erik.Bjork@stripped wrote:
> #At file:///home/lb200670/devel/mysql/checkin/
>
> 2859 lars-erik.bjork@stripped 2008-10-07
> This is a fix for bug#39647 (Warning about slow serial log writes should be
> prefixed with time stamp)
>
> This fix prefixes time stamps on all messages sent through the interface
> provided by the Log class. StorageInterface::logger is registered as a receiver of the
> log, and
> all messages received are prefixed before being printed. This ensures that
> other future/historic receivers of the log are not forced to have the Falcon specific time
>
> stamp. The time stamps are on the format YYMMDD (h)h:mm:ss, to be in line with
> the time stamps printed by the server and by InnoDB.
> modified:
> storage/falcon/ha_falcon.cpp
>
> === modified file 'storage/falcon/ha_falcon.cpp'
> --- a/storage/falcon/ha_falcon.cpp 2008-10-03 05:15:40 +0000
> +++ b/storage/falcon/ha_falcon.cpp 2008-10-07 07:18:30 +0000
> @@ -19,6 +19,8 @@
> #define MYSQL_SERVER
> #endif
>
> +#include <time.h>
> +
> #include "mysql_priv.h"
> #include "falcon_probes.h"
>
> @@ -173,6 +175,38 @@ bool checkExceptionSupport()
> return false;
> }
>
> +void getTimestamp(int length, char* buffer)
> +{
> +#ifdef __WIN__
> + SYSTEMTIME now;
> + GetLocalTime(&now);
> + snprintf(buffer, length, "%.2d%.2d%.2d %2d:%.2d:%.2d",
> + (int)now.wYear % 100,
> + (int)now.wMonth,
> + (int)now.wDay,
> + (int)now.wHour,
> + (int)now.wMinute,
> + (int)now.wSecond);
> +#else
> + struct tm result;
> + time_t now;
> + time(&now);
> +#ifdef HAVE_LOCALTIME_R
> + struct tm* time_ptr = localtime_r(&now, &result);
> +#else
> + struct tm* time_ptr = localtime(&now);
> + result = *time_ptr;
> +#endif
> + snprintf(buffer, length, "%.2d%.2d%.2d %2d:%.2d:%.2d",
> + (int)result.tm_year % 100,
> + (int)result.tm_mon + 1,
> + (int)result.tm_mday,
> + (int)result.tm_hour,
> + (int)result.tm_min,
> + (int)result.tm_sec);
> +#endif
> +}
> +
> int StorageInterface::falcon_init(void *p)
> {
> DBUG_ENTER("falcon_init");
> @@ -2358,12 +2392,14 @@ void StorageInterface::logger(int mask,
> {
> if (mask & falcon_debug_mask)
> {
> - printf("%s", text);
> + char time[256];
> + getTimestamp(sizeof(time), time);
> + printf("%s Falcon: %s", time, text);
> fflush(stdout);
>
> if (falcon_log_file)
> {
> - fprintf(falcon_log_file, "%s", text);
> + fprintf(falcon_log_file, "%s Falcon: %s", time, text);
> fflush(falcon_log_file);
> }
> }
>
>
>
