logging with iostream/stdio/mmap

iostream/stdio とあと mmap を使って 簡易logging のベンチマークとか。

結果

iostream

1.76625 usec

stdio

1.24158 usec

mmap

0.987958 usec

logging の呼び出し１回あたりの計算時間がこんな感じ。環境は Intel Core2 Duo 2.0GHz + gcc 4.0.1 on MacBook
しかし、iostream が結構遅いな。

#include <iostream>
#include <unistd.h>
#include <sys/time.h>

static const size_t NUM_ITERATE = 500000;

static const char* MESSAGE = "statement for logging performance "
    "test scenario";

extern void logging(const char* message);
extern void init(void);
extern void destroy(void);

int
main()
{
  struct timeval start, end;
  unsigned long long elapsed;

  init();

  gettimeofday(&start, NULL);
  for (size_t i = 0; i < NUM_ITERATE; i++)
    {
      logging(MESSAGE);
    }
  gettimeofday(&end, NULL);

  destroy();

  elapsed = (end.tv_sec - start.tv_sec) * 1000000 +
    (end.tv_usec - start.tv_usec);

  std::cout << static_cast<double>(elapsed) / NUM_ITERATE << std::endl;
}

#include <fstream>
#include <iomanip>
#include <cassert>
#include <unistd.h>
#include <sys/time.h>
#include <climits>

static const char* LOG_DIR = "log/iostream";
static const size_t LIMIT = 1024 * 1024;
static const size_t SIZE_OF_HEADER = 20;

static int log_no = 0;
static int pos;
static std::ofstream out;
static pthread_mutex_t mutex = PTHREAD_MUTEX_INITIALIZER;

static void open_log()
{
  if (out.is_open())
    {
      out.close();
    }

  log_no++;
  char filename[PATH_MAX];
  sprintf(filename, "%s/%02d", LOG_DIR, log_no);
  out.open(filename);

  if (!out)
    {
      perror("std::ofstream::open");
      exit(EXIT_FAILURE);
    }

  pos = 0;
}

void init()
{
  pos = 0;
}

void destroy()
{
  if (out.is_open())
    {
      out.close();
    }
}

void logging(const char* message)
{
  int st;
  struct timeval tv;
  size_t len = strlen(message);

  st = gettimeofday(&tv, NULL);
  assert(st == 0);

  pthread_mutex_lock(&mutex);
  if (pos + len + SIZE_OF_HEADER + 1 > LIMIT || !out.is_open())
    {
      open_log();
    }

  out << std::setw(10) << tv.tv_sec << '.'
      << std::setw(6) << std::setfill('0') << tv.tv_usec
      << " : "
      << message << '\n';

  pos += SIZE_OF_HEADER + len + 1;

  pthread_mutex_unlock(&mutex);
}

#include <cstdio>
#include <cstdlib>
#include <cassert>
#include <climits>
#include <cstring>
#include <unistd.h>
#include <sys/time.h>
#include <pthread.h>

static const char* LOG_DIR = "log/stdio";
static const size_t SIZE_OF_HEADER = 20;
static const size_t LIMIT = 1024 * 1024;

static int log_no;
static FILE* fp;
static int pos;
static pthread_mutex_t mutex = PTHREAD_MUTEX_INITIALIZER;

static void open_log()
{
  if (fp != NULL)
    {
      fclose(fp);
    }

  log_no++;
  char filename[PATH_MAX];
  sprintf(filename, "%s/%02d", LOG_DIR, log_no);

  fp = fopen(filename, "w");
  if (fp == NULL)
    {
      perror("fopen");
      exit(EXIT_FAILURE);
    }

  pos = 0;
}

void init()
{
  log_no = 0;
  fp = NULL;
}

void destroy()
{
  if (fp != NULL)
    {
      fclose(fp);
    }
}

void logging(const char* message)
{
  size_t len = strlen(message);
  size_t n;
  struct timeval tv;
  int st;

  pthread_mutex_lock(&mutex);
  if (pos + len + SIZE_OF_HEADER + 1 > LIMIT || fp == NULL)
    {
      open_log();
    }

  st = gettimeofday(&tv, NULL);
  assert(st == 0);
  n = fprintf(fp, "%ld.%06ld : %s\n", tv.tv_sec, tv.tv_usec, message);
  pos += n;
  pthread_mutex_unlock(&mutex);
}

#include <stdio.h>
#include <fcntl.h>
#include <sys/mman.h>
#include <unistd.h>
#include <sys/time.h>
#include <cassert>
#include <cstring>
#include <climits>
#include <pthread.h>

static int fd;
static char *buffer;
static size_t pos;
static int log_no;
static pthread_mutex_t mutex = PTHREAD_MUTEX_INITIALIZER;

static const char* LOG_DIR = "log/mmap";
static const size_t LIMIT = 1024 * 1024;
static const size_t SIZE_OF_HEADER = 20;

static void open_log()
{
  char filename[PATH_MAX];
  int st;
  log_no++;

  if (fd >= 0)
    {
      munmap(buffer, LIMIT);
      ftruncate(fd, pos);
      close(fd);
    }

  sprintf(filename, "%s/%02d", LOG_DIR, log_no);
  fd = open(filename, O_RDWR | O_CREAT, 0600);
  if (fd == -1)
    {
      perror("open");
      exit(EXIT_FAILURE);
    }

  st = ftruncate(fd, LIMIT);
  if (st == -1)
    {
      perror("ftruncate");
      exit(EXIT_FAILURE);
    }

  buffer = reinterpret_cast<char *>(mmap(NULL, LIMIT, PROT_WRITE, MAP_SHARED, fd, 0));

  if (buffer == reinterpret_cast<char *>(-1))
    {
      perror("mmap");
      exit(EXIT_FAILURE);
    }

  pos = 0;
}

void init()
{
  fd = -1;
  log_no = 0;
}

void destroy()
{
  if (fd >= 0)
    {
      munmap(buffer, LIMIT);
      ftruncate(fd, pos);
      close(fd);
    }
}

void logging(const char* message)
{
  size_t len = strlen(message);
  size_t n = 0;
  struct timeval tv;
  gettimeofday(&tv, NULL);

  pthread_mutex_lock(&mutex);
  if (pos + len + SIZE_OF_HEADER + 1 > LIMIT || log_no == 0)
    {
      open_log();
    }

  n = sprintf(buffer + pos, "%10d.%06d : %s\n",
              tv.tv_sec, tv.tv_usec, message);
  pos += n;

  pthread_mutex_unlock(&mutex);
}