server/common/logger.C

/*
 * This file is part of Deliantra, the Roguelike Realtime MMORPG.
 * 
 * Copyright (©) 2005,2006,2007,2008,2009,2010 Marc Alexander Lehmann / Robin Redeker / the Deliantra team
 * 
 * Deliantra is free software: you can redistribute it and/or modify it under
 * the terms of the Affero GNU General Public License as published by the
 * Free Software Foundation, either version 3 of the License, or (at your
 * option) any later version.
 * 
 * This program is distributed in the hope that it will be useful,
 * but WITHOUT ANY WARRANTY; without even the implied warranty of
 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
 * GNU General Public License for more details.
 * 
 * You should have received a copy of the Affero GNU General Public License
 * and the GNU General Public License along with this program. If not, see
 * <http://www.gnu.org/licenses/>.
 * 
 * The authors can be reached via e-mail to <support@deliantra.net>
 */

#include <cstdarg>
#include <cstring>

#include <vector>

#include <sys/uio.h>
#include <pthread.h>

#include "global.h"
#include "dynbuf.h"
#include "util.h"

struct logline
{
  struct timeval tv;
  char *buf; // includes PREFIX_LEN garbage bytes
  int len;
  int flags;
};

typedef std::vector<logline, slice_allocator<logline> > logvector;

static SMUTEX(mutex);
static SMUTEX(fdlock);
static SCOND(cond);
static int logfd = STDERR_FILENO;
static int logsync = 1;
static logvector queue;

int log_setfd (int fd)
{
  SMUTEX_LOCK (fdlock);
  int old = logfd;
  logfd = fd < 0 ? STDERR_FILENO : fd;
  SMUTEX_UNLOCK (fdlock);

  return old;
}

#define PREFIX_LEN sizeof ("0000-00-00 00:00:00.0000+") - 1

static void
log_sync (logline &line)
{
  struct tm lt;
  char pfx [PREFIX_LEN];

  localtime_r (&line.tv.tv_sec, &lt);

  sprintf (pfx, "%04d-%02d-%02d %02d:%02d:%02d.%04d",
    lt.tm_year + 1900,
    lt.tm_mon + 1,
    lt.tm_mday,
    lt.tm_hour,
    lt.tm_min,
    lt.tm_sec,
    (int)(line.tv.tv_usec / 100)
  );

  pfx [PREFIX_LEN - 1] = line.flags & logSync ? '=' : ' ';

  struct iovec iov [2];

  iov [0].iov_base = pfx;
  iov [0].iov_len = PREFIX_LEN;

  char *buf = line.buf;

  if (logsync != 2)
    SMUTEX_LOCK (fdlock);

  while (char *end = strchr (buf, '\n'))
    {
      iov [1].iov_base = buf;
      iov [1].iov_len = end - buf + 1;

      writev (STDERR_FILENO, iov, 2);
      if (logfd != STDERR_FILENO)
        writev (logfd, iov, 2);

      buf = end + 1;

      if (buf == line.buf + line.len)
        break;

      pfx [PREFIX_LEN - 1] = '+';
    }

  if (logsync != 2)
    SMUTEX_UNLOCK (fdlock);

  sfree (line.buf, line.len);
}

static void *
logthread_proc (void *arg)
{
  int idx = 0;

  for (;;)
    {
      logline line;

      SMUTEX_LOCK (mutex);

      while (queue.empty ())
        SCOND_WAIT (cond, mutex);

      line = queue [idx++];

      // this algorithm could result in an ever-increasing vector
      // size if we log faster than we can write, but if that happens
      // we have bigger problems.
      if (idx == queue.size ())
        {
          if (idx < 32)
            queue.clear ();
          else
            logvector ().swap (queue); // free memory, hopefully

          idx = 0;
        }

      SMUTEX_UNLOCK (mutex);

      log_sync (line);
    }
}

void
log_cleanup ()
{
  logsync = 1;
  SMUTEX_UNLOCK (fdlock);

  for (;;)
    {
      int done;

      SMUTEX_LOCK (mutex);
      done = queue.empty ();
      SMUTEX_UNLOCK (mutex);

      if (done)
        break;

      usleep (10000);
      SMUTEX_LOCK (fdlock);
      SMUTEX_UNLOCK (fdlock);
    }
}

static void
af_child ()
{
  logsync = 2;
}

static struct logthread : thread
{
  logthread ()
  {
    pthread_atfork (0, 0, af_child);
    start (logthread_proc);
    logsync = 0;
  }
} logthread;

void
LOG (int flags, const_utf8_string format, ...)
{
  int level = flags & 15;

  if (level > settings.debug)
    return;

  logline line;
  gettimeofday (&line.tv, 0);

  static dynbuf_text buf;

  va_list ap;
  va_start (ap, format);
  buf.vprintf (format, ap);
  va_end (ap);

  buf << '\n';

  line.buf = buf.linearise ();
  line.len = buf.size ();

  if (line.buf [line.len - 2] == '\n')
    --line.len;

  line.buf = salloc<char> (line.len, line.buf);

  buf.clear ();

  if (logsync)
    flags |= logSync;

  if (flags & logBacktrace)
    {
      line.buf [line.len - 1] = 0;
      log_backtrace (line.buf);
      line.buf [line.len - 1] = '\n';
    }

  line.flags = flags;

  if (line.flags & logSync)
    log_sync (line);
  else
    {
      SMUTEX_LOCK (mutex);
      queue.push_back (line);
      SMUTEX_UNLOCK (mutex);
      SCOND_SIGNAL (cond);
    }
}

static int suspended;

void
log_suspend ()
{
  if (!suspended++)
    {
      LOG (llevDebug, "logging suspended.");
      SMUTEX_LOCK (fdlock);
    }
}

void
log_resume ()
{
  if (!--suspended)
    {
      SMUTEX_UNLOCK (fdlock);
      LOG (llevDebug, "logging resumed.");
    }
}

Revision:	1.25
Committed:	Sun Apr 11 17:54:13 2010 UTC (14 years, 1 month ago) by root
Content type:	text/plain
Branch:	MAIN
Changes since 1.24:	+9 -2 lines
Log Message:	tuning...
#	User	Rev	Content
1	elmex	1.1	/*
2	root	1.16	* This file is part of Deliantra, the Roguelike Realtime MMORPG.
3	pippijn	1.11	*
4	root	1.23	* Copyright (©) 2005,2006,2007,2008,2009,2010 Marc Alexander Lehmann / Robin Redeker / the Deliantra team
5	pippijn	1.11	*
6	root	1.20	* Deliantra is free software: you can redistribute it and/or modify it under
7			* the terms of the Affero GNU General Public License as published by the
8			* Free Software Foundation, either version 3 of the License, or (at your
9			* option) any later version.
10	pippijn	1.11	*
11	root	1.15	* This program is distributed in the hope that it will be useful,
12			* but WITHOUT ANY WARRANTY; without even the implied warranty of
13			* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
14			* GNU General Public License for more details.
15	pippijn	1.11	*
16	root	1.20	* You should have received a copy of the Affero GNU General Public License
17			* and the GNU General Public License along with this program. If not, see
18			* <http://www.gnu.org/licenses/>.
19	root	1.13	*
20	root	1.16	* The authors can be reached via e-mail to <support@deliantra.net>
21	pippijn	1.11	*/
22	elmex	1.1
23	root	1.12	#include <cstdarg>
24	root	1.17	#include <cstring>
25
26			#include <vector>
27
28			#include <sys/uio.h>
29			#include <pthread.h>
30
31			#include "global.h"
32			#include "dynbuf.h"
33			#include "util.h"
34
35			struct logline
36			{
37			struct timeval tv;
38			char *buf; // includes PREFIX_LEN garbage bytes
39			int len;
40			int flags;
41			};
42
43	root	1.25	typedef std::vector<logline, slice_allocator<logline> > logvector;
44
45	root	1.17	static SMUTEX(mutex);
46	root	1.24	static SMUTEX(fdlock);
47	root	1.17	static SCOND(cond);
48			static int logfd = STDERR_FILENO;
49			static int logsync = 1;
50	root	1.25	static logvector queue;
51	root	1.17
52	root	1.24	int log_setfd (int fd)
53	root	1.17	{
54	root	1.24	SMUTEX_LOCK (fdlock);
55			int old = logfd;
56	root	1.17	logfd = fd < 0 ? STDERR_FILENO : fd;
57	root	1.24	SMUTEX_UNLOCK (fdlock);
58
59			return old;
60	root	1.17	}
61
62			#define PREFIX_LEN sizeof ("0000-00-00 00:00:00.0000+") - 1
63
64			static void
65			log_sync (logline &line)
66			{
67	root	1.18	struct tm lt;
68	root	1.17	char pfx [PREFIX_LEN];
69
70	root	1.18	localtime_r (&line.tv.tv_sec, &lt);
71
72	root	1.17	sprintf (pfx, "%04d-%02d-%02d %02d:%02d:%02d.%04d",
73	root	1.18	lt.tm_year + 1900,
74			lt.tm_mon + 1,
75			lt.tm_mday,
76			lt.tm_hour,
77			lt.tm_min,
78			lt.tm_sec,
79	root	1.17	(int)(line.tv.tv_usec / 100)
80			);
81
82			pfx [PREFIX_LEN - 1] = line.flags & logSync ? '=' : ' ';
83
84			struct iovec iov [2];
85
86			iov [0].iov_base = pfx;
87			iov [0].iov_len = PREFIX_LEN;
88
89			char *buf = line.buf;
90
91	root	1.24	if (logsync != 2)
92			SMUTEX_LOCK (fdlock);
93
94	root	1.17	while (char *end = strchr (buf, '\n'))
95			{
96			iov [1].iov_base = buf;
97			iov [1].iov_len = end - buf + 1;
98
99			writev (STDERR_FILENO, iov, 2);
100			if (logfd != STDERR_FILENO)
101			writev (logfd, iov, 2);
102
103			buf = end + 1;
104
105			if (buf == line.buf + line.len)
106			break;
107
108			pfx [PREFIX_LEN - 1] = '+';
109			}
110
111	root	1.24	if (logsync != 2)
112			SMUTEX_UNLOCK (fdlock);
113
114	root	1.17	sfree (line.buf, line.len);
115			}
116
117			static void *
118			logthread_proc (void *arg)
119			{
120			int idx = 0;
121
122			for (;;)
123			{
124			logline line;
125
126			SMUTEX_LOCK (mutex);
127
128			while (queue.empty ())
129			SCOND_WAIT (cond, mutex);
130
131			line = queue [idx++];
132
133			// this algorithm could result in an ever-increasing vector
134			// size if we log faster than we can write, but if that happens
135			// we have bigger problems.
136			if (idx == queue.size ())
137			{
138	root	1.25	if (idx < 32)
139			queue.clear ();
140			else
141			logvector ().swap (queue); // free memory, hopefully
142
143	root	1.17	idx = 0;
144			}
145
146			SMUTEX_UNLOCK (mutex);
147
148			log_sync (line);
149			}
150			}
151
152			void
153			log_cleanup ()
154			{
155			logsync = 1;
156	root	1.25	SMUTEX_UNLOCK (fdlock);
157	root	1.17
158			for (;;)
159			{
160			int done;
161
162			SMUTEX_LOCK (mutex);
163			done = queue.empty ();
164			SMUTEX_UNLOCK (mutex);
165
166			if (done)
167			break;
168
169			usleep (10000);
170	root	1.24	SMUTEX_LOCK (fdlock);
171			SMUTEX_UNLOCK (fdlock);
172	root	1.17	}
173			}
174
175			static void
176			af_child ()
177			{
178	root	1.24	logsync = 2;
179	root	1.17	}
180
181			static struct logthread : thread
182			{
183			logthread ()
184			{
185			pthread_atfork (0, 0, af_child);
186			start (logthread_proc);
187			logsync = 0;
188			}
189			} logthread;
190	elmex	1.1
191	root	1.4	void
192	root	1.22	LOG (int flags, const_utf8_string format, ...)
193	elmex	1.1	{
194	root	1.12	int level = flags & 15;
195
196			if (level > settings.debug)
197			return;
198
199	root	1.17	logline line;
200			gettimeofday (&line.tv, 0);
201	root	1.12
202	root	1.17	static dynbuf_text buf;
203	root	1.12
204			va_list ap;
205			va_start (ap, format);
206	root	1.17	buf.vprintf (format, ap);
207	root	1.12	va_end (ap);
208
209	root	1.17	buf << '\n';
210
211			line.buf = buf.linearise ();
212			line.len = buf.size ();
213	root	1.12
214	root	1.17	if (line.buf [line.len - 2] == '\n')
215			--line.len;
216	root	1.14
217	root	1.17	line.buf = salloc<char> (line.len, line.buf);
218
219			buf.clear ();
220
221			if (logsync)
222			flags \|= logSync;
223	root	1.12
224			if (flags & logBacktrace)
225	root	1.17	{
226			line.buf [line.len - 1] = 0;
227			log_backtrace (line.buf);
228			line.buf [line.len - 1] = '\n';
229			}
230
231			line.flags = flags;
232
233			if (line.flags & logSync)
234			log_sync (line);
235			else
236			{
237			SMUTEX_LOCK (mutex);
238			queue.push_back (line);
239			SMUTEX_UNLOCK (mutex);
240			SCOND_SIGNAL (cond);
241			}
242	elmex	1.1	}
243	root	1.17
244	root	1.24	static int suspended;
245
246			void
247			log_suspend ()
248			{
249			if (!suspended++)
250			{
251			LOG (llevDebug, "logging suspended.");
252			SMUTEX_LOCK (fdlock);
253			}
254			}
255
256			void
257			log_resume ()
258			{
259			if (!--suspended)
260			{
261			SMUTEX_UNLOCK (fdlock);
262			LOG (llevDebug, "logging resumed.");
263			}
264			}
265