On Tue, Oct 05, 2010 at 04:50:20PM +0200, Dejan Muhamedagic wrote:
> Hi Lars,
>
> On Mon, Oct 04, 2010 at 08:23:17PM +0200, Lars Ellenberg wrote:
> > # HG changeset patch
> > # User Lars Ellenberg <l...@linbit.com>
> > # Date 1286216544 -7200
> > # Node ID b59be1e5279175464c3afb1b467531580f49da8b
> > # Parent 0285b706fcde4d989291ab845ed245f1c366bf1e
> > Medium: add fflush back to cl_log
> >
> > diff -r 0285b706fcde -r b59be1e52791 include/clplumbing/cl_log.h
> > --- a/include/clplumbing/cl_log.h Tue Sep 28 19:10:38 2010 +0200
> > +++ b/include/clplumbing/cl_log.h Mon Oct 04 20:22:24 2010 +0200
> > @@ -34,6 +34,11 @@
> > #define DEBUGPKT (debug_level >= 4)
> > #define DEBUGPKTCONT (debug_level >= 5)
> >
> > +/* no_fflush and do_fflush as optimization for the logging daemon,
> > + * so it may buffer a few message lines, then fflush them out in one write.
> > + * set do_fsync != 0, if you even want it to fsync. */
> > +void cl_direct_log_no_fflush(int priority, const char* buf,
> > gboolean, const char*, int, TIME_T);
> > +void cl_direct_log_do_fflush(int do_fsync);
> > void cl_direct_log(int priority, const char* buf, gboolean,
> > const char*, int, TIME_T);
> > void cl_log(int priority, const char * fmt, ...)
> > G_GNUC_PRINTF(2,3);
> > void cl_perror(const char * fmt, ...) G_GNUC_PRINTF(1,2);
> > diff -r 0285b706fcde -r b59be1e52791 lib/clplumbing/cl_log.c
> > --- a/lib/clplumbing/cl_log.c Tue Sep 28 19:10:38 2010 +0200
> > +++ b/lib/clplumbing/cl_log.c Mon Oct 04 20:22:24 2010 +0200
> > @@ -522,10 +522,15 @@
> > * non-blocking IPC.
> > */
> >
> > +/* As performance optimization we keep the file-handle
> > + * open all the time */
> > +static FILE * log_fp = NULL;
> > +static FILE * debug_fp = NULL;
> > +
> > /* Cluster logging function */
> > -void
> > -cl_direct_log(int priority, const char* buf, gboolean use_priority_str,
> > - const char* entity, int entity_pid, TIME_T ts)
> > +static void
> > +cl_direct_log_(int priority, const char* buf, gboolean use_priority_str,
> > + const char* entity, int entity_pid, TIME_T ts, int do_fflush)
> > {
> > const char * pristr;
> > int needprivs = !cl_have_full_privs();
> > @@ -558,27 +563,25 @@
> > }
> >
> > if (debugfile_name != NULL) {
> > - static FILE * debug_fp = NULL;
> > if (!debug_fp) {
> > - /* As performance optimization we keep the file-handle
> > - * open all the time */
> > debug_fp = open_log_file(debugfile_name);
> > }
> > - if (debug_fp)
> > - append_log(debug_fp ,entity, entity_pid, ts, pristr,
> > - buf);
> > + if (debug_fp) {
> > + append_log(debug_fp ,entity, entity_pid, ts, pristr,
> > buf);
> > + if (do_fflush)
> > + fflush(debug_fp);
> > + }
> > }
> >
> > if (priority != LOG_DEBUG && logfile_name != NULL) {
> > - static FILE * log_fp = NULL;
> > if (!log_fp) {
> > - /* As performance optimization we keep the file-handle
> > - * open all the time */
> > log_fp = open_log_file(logfile_name);
> > }
> > - if (log_fp)
> > - append_log(log_fp ,entity, entity_pid, ts, pristr,
> > - buf);
> > + if (log_fp) {
> > + append_log(log_fp ,entity, entity_pid, ts, pristr, buf);
> > + if (do_fflush)
> > + fflush(log_fp);
> > + }
> > }
> >
> > if (needprivs) {
> > @@ -588,7 +591,35 @@
> > return;
> > }
> >
> > +void
> > +cl_direct_log(int priority, const char* buf, gboolean use_priority_str,
> > + const char* entity, int entity_pid, TIME_T ts)
> > +{
> > + cl_direct_log_(priority, buf, use_priority_str,
> > + entity, entity_pid, ts, 1);
> > +}
> >
> > +void
> > +cl_direct_log_no_fflush(int priority, const char* buf, gboolean
> > use_priority_str,
> > + const char* entity, int entity_pid, TIME_T ts)
> > +{
> > + cl_direct_log_(priority, buf, use_priority_str,
> > + entity, entity_pid, ts, 0);
> > +}
> > +
> > +void cl_direct_log_do_fflush(int do_fsync)
> > +{
> > + if (log_fp) {
> > + fflush(log_fp);
> > + if (do_fsync)
> > + fsync(fileno(log_fp));
> > + }
> > + if (debug_fp) {
> > + fflush(debug_fp);
> > + if (do_fsync)
> > + fsync(fileno(debug_fp));
> > + }
> > +}
> >
> > /*
> > * This function can cost us realtime unless use_logging_daemon
> > diff -r 0285b706fcde -r b59be1e52791 logd/ha_logd.c
> > --- a/logd/ha_logd.c Tue Sep 28 19:10:38 2010 +0200
> > +++ b/logd/ha_logd.c Mon Oct 04 20:22:24 2010 +0200
> > @@ -750,10 +750,9 @@
> > static gboolean
> > direct_log(IPC_Channel* ch, gpointer user_data)
> > {
> > -
> > IPC_Message* ipcmsg;
> > GMainLoop* loop;
> > -
> > + int pri = LOG_DEBUG + 1;
> >
> > loop =(GMainLoop*)user_data;
> >
> > @@ -791,7 +790,9 @@
> > , copy.use_pri_str
> > , copy.entity, copy.entity_pid
> > , copy.timestamp);
> > -
> > +
> > + if (copy.priority < pri)
> > + pri = copy.priority;
> >
> > (void)logd_log;
> > /*
> > @@ -810,6 +811,8 @@
> > }
> >
> > }
> > + cl_direct_log_do_fflush(pri <= LOG_ERR);
> > +
> > if(needs_shutdown) {
> > cl_log(LOG_INFO, "Exiting write process");
> > g_main_quit(loop);
>
> I like the patch. The idea with flush depending on priority is
> good.
No, the _fsync_ was depending on priority. The fflush is unconditional,
but batched to possibly multiple lines.
> Unfortunately, there's a queue of patches for cl_log which I
> didn't find time yet to review. They were posted by Bernd
> Schubert to the pacemaker ML more than a month ago. I'm afraid
> I've been doing a bad job lately :(
Well, one of those patches is in (the "keep the fd open for the
lifetime"), and it breaks things.
Previously, it would open, append a message, then close the fd,
and the close results in fflush as well.
Now it only fprintf's, no fflush done, by default we are "block
buffered", so one "BUFSIZE" worth of log lines may hang indefinetely
in the stdio buffers, and concurrent direct loggers may
append into half written lines.
I think we actually had to do it linebuffered, but we may be ok if we
assume that most logging goes through logd, and thus we only have one
writer usually, so the chance for interleaved half-written lines is very
small, if we at least fflush after ever batch of log lines.
> Also, Keisuke-san has concerns about that latest patch (also by
> Bernd) which did make it into the glue repository. See the
> bugzilla report at
>
> http://developerbugs.linux-foundation.org/show_bug.cgi?id=2470
Bernd himself adds fflush back in with the patch in Comment #6
http://developerbugs.linux-foundation.org/show_bug.cgi?id=2470#c6
But yes,
log rotation needs to go in again, too, I suggest
SIGHUP handling, and add a "reload" action to the init script
to be used by the postrotate trigger.
Re "static functions" are not used outside that file... that is not
true. They may still be members of function pointer tables, which may be
exported ;-)
And yes, heartbeat (and all other users of cl_log) may end up doing
cl_direct_log, sometimes even though logd is configured.
So in theory all of them would have to be signaled from logrotate.
Maybe forget about the "reload" mentioned previously,
rather use "fuser -HUP -k $LOGFILE_AFTER_MOVE_BEFORE_COMPRESSION"?
Too bad if they don't handle HUP, the cluster stack will likely reboot ;-)
Maybe do "delayed compression" in logrotate, and have a stat() every Nth
logline, to possibly re-open the files?
--
: Lars Ellenberg
: LINBIT | Your Way to High Availability
: DRBD/HA support and consulting http://www.linbit.com
DRBD® and LINBIT® are registered trademarks of LINBIT, Austria.
_______________________________________________________
Linux-HA-Dev: Linux-HA-Dev@lists.linux-ha.org
http://lists.linux-ha.org/mailman/listinfo/linux-ha-dev
Home Page: http://linux-ha.org/
