Multi-thread logging efficiency

[myaegean]

I provided a logging functionality to provide about 15 threads output there logs to a log file. So I used a mutex lock to serialize the logging process. In concurrency testing, a single thread logging 3,000,000 times costs 10 seconds, while 15 threads logging 200,000 times cost about 42 seconds

[jack@bjqa-test05 multi-thread-logging]$ ./a.out
2014-07-11 11:34:04 [INF] MODA: Test_LogConcurrencyWithPress: Single thread logging (3000000)times cost(10s)
2014-07-11 11:34:23 [INF] MODA: Test_LogConcurrencyWithPress: multiple(15) threads logging (200000) times for each, cost(42s)
[jack@bjqa-test05 multi-thread-logging]$

I'm wondering if there is a method to improve(maybe just a little) the logging efficiency. I don't need to support millions of concurrency, I just don't want all the threads waiting and waiting to output there logs to my logging functionality.

The following is the detail codes logging.c and logging.h

#include <stdarg.h>
#include <string.h>
#include <time.h>
#include <assert.h>
#include <math.h>
#include <pthread.h>
#include "logging.h"

static FILE * s_pFile = NULL;
static char * s_pDirName = "log/";
static char * s_pFileName = "logging";
static unsigned int s_uiFileNum = 0;
static unsigned int s_uiLineCount = 0;

static pthread_mutex_t s_mutex;

/* Log level */
static char s_acLevel[LOG_MAX_LEVEL][8] = { "INF", "WAR", "ERR", "INF" };

/* Log module */
static char s_acModule[LOG_MAX_MOD - LOG_MIN_MOD - 1][8] = {
                          "MOD1", 
                          "MOD2",
                          "MOD3", 
                          "MOD4", 
                          "MOD5", 
                          "MOD6", 
                          "MOD7",  
                          "MOD8",  
                          "MOD9",  
                          "MODA",  
                          "MODB", 
                          "MODC",  
                          "MODD",  
                          "MODE",  
                          "MODF", 
                          "MODG",  
                          "MODH"   
                         };

/* Timestamp for log file name (conpact format) */
static void LOG_GetTime(char *pStrBuf)
{
    time_t now;
    struct tm *tm_now;

    if (NULL == pStrBuf)
    {
        return;
    }

    time(&now);
    tm_now = localtime(&now);
    sprintf(pStrBuf, "%d%02d%02d%02d%02d%02d", tm_now->tm_year + 1900, tm_now->tm_mon+1, tm_now->tm_mday, 
                      tm_now->tm_hour, tm_now->tm_min, tm_now->tm_sec);

    return;
}

/* Timestamp for log message (loose format) */
static void LOG_GetTimestamp(char *pStrBuf)
{
    time_t now;
    struct tm *tm_now;

    if (NULL == pStrBuf)
    {
        return;
    }


    time(&now);
    tm_now = localtime(&now);
    sprintf(pStrBuf, "%d-%02d-%02d %02d:%02d:%02d", tm_now->tm_year + 1900, tm_now->tm_mon+1, tm_now->tm_mday, tm_now->tm_hour, tm_now->tm_min, tm_now->tm_sec);

    return;
}

/* Log rotate: add time stamps to log file name, so each log file will be different from the others */
static int LOG_Rotate()
{
    int iRet = -1;

    char acDate[LOG_DATE_LEN + 1];
    char acFileNameNew[LOG_FILENAME_LEN + 1];
    char acFileNameOld[LOG_FILENAME_LEN + 1];

    memset(acDate, 0x00, LOG_DATE_LEN+1);
    LOG_GetTime(acDate);

    memset(acFileNameOld, 0x00, LOG_FILENAME_LEN + 1);
    sprintf(acFileNameOld, "%s%s.txt", s_pDirName, s_pFileName);

    memset(acFileNameNew, 0x00, LOG_FILENAME_LEN + 1);
    sprintf(acFileNameNew, "%s%s_%s_%04d.txt", s_pDirName, s_pFileName, acDate, s_uiFileNum);

    iRet = rename(acFileNameOld, acFileNameNew);
    if (0 != iRet)
    {
        printf("Error, failed to call rename %s to %s.\n", acFileNameOld, acFileNameNew);
        return -1;
    }

    /* Log file number threshold checking */
    if (s_uiFileNum >= MAX_LOG_FILE_NUM)
    {
        printf("Error, maximum file number reached(%d)!!!!\n", s_uiFileNum);
        assert(0);
    }

    return 0;
}

int LOG_Init()
{
    char acFileFullName[LOG_FILENAME_LEN + 1];
    int iRet = -1;

    memset(acFileFullName, 0x00, LOG_FILENAME_LEN + 1);
    sprintf(acFileFullName, "%s%s.txt", s_pDirName, s_pFileName);
    s_pFile = fopen(acFileFullName, "w+");
    if (NULL == s_pFile)
    {
        printf("[ERROR]LOG_Init: Failed to open file %s.\n", acFileFullName);
        return -1;
    }

    /* Mutex lock initialize */
    iRet = pthread_mutex_init(&s_mutex, NULL);;
    if (0 != iRet)
    {
        printf("[ERROR]LOG_Init: Failed to call pthread_mutex_init()\n");
        return -1;
    }

    s_uiLineCount = 0;
    s_uiFileNum ++;

    return 0;
}

void LOG_Logging(int iLevel, int iModule, char * pStrFormat, ...)
{
    char acMsg[LOG_MSG_LEN + 1];
    char acDate[LOG_DATE_LEN + 1];
    char acBuf[LOG_BUF_LEN + 1];

    va_list list;
    va_start(list, pStrFormat);

    /* Parameters check */
    if (iModule <= LOG_MIN_MOD || iModule >= LOG_MAX_MOD || iLevel >= LOG_MAX_LEVEL)
    {
        assert(0);
    }

    /* Get message content */
    memset(acMsg, 0x00, LOG_MSG_LEN + 1);
    vsnprintf(acMsg, LOG_BUF_LEN + 1, pStrFormat, list);

    /* Get time stamp */
    memset(acDate, 0x00, LOG_DATE_LEN + 1);
    LOG_GetTimestamp(acDate);

    /* Format log messages to write to file */
    memset(acBuf, 0x00, sizeof(acBuf));
    sprintf(acBuf, "%s [%s] %s: %s", acDate, s_acLevel[iLevel], s_acModule[iModule - LOG_MIN_MOD -1], acMsg);

    pthread_mutex_lock(&s_mutex);

    /* Output the error message directly to screen. */
    if (iLevel == LERR || iLevel == LSCR)
    {
        printf(acBuf);
    }

    /* Log file rotate, if the threshold (maximum line number) reached */
    if (s_uiLineCount >= MAX_LOG_LINE_NUM)
    {
        fclose(s_pFile);
        s_pFile = NULL;

        LOG_Rotate();
        LOG_Init();
    }

    fputs(acBuf, s_pFile);
    fflush(s_pFile);
    s_uiLineCount++;

    pthread_mutex_unlock(&s_mutex);

    va_end(list);
    return;
}


void LOG_Close()
{
    if(NULL == s_pFile)
    {
        return;
    }

    fclose(s_pFile);
    s_pFile = NULL;

    LOG_Rotate();

    pthread_mutex_destroy(&s_mutex);
    return;
}

/*********************************************************/
/* logging.h */

#ifndef _LOGGING_H_
#define _LOGGING_H_

#include <stdio.h>

#define MAX_LOG_LINE_NUM 500000 /* Max line number of a single file */
#define MAX_LOG_FILE_NUM 9999
#define LOG_BUF_LEN      256
#define LOG_MSG_LEN      128
#define LOG_FILENAME_LEN 64
#define LOG_DATE_LEN     32
#define LOG_MODULE_LEN   16
#define LOG_MAX_LEVEL    4


/* Values for 2nd parameter of LOG_Logging() */
enum enLogModules
{
    LOG_MIN_MOD = 100,
    LOG_MOD1,         
    LOG_MOD2,        
    LOG_MOD3,         
    LOG_MOD4,         
    LOG_MOD5,         
    LOG_MOD6,       
    LOG_MOD7,      
    LOG_MOD8,      
    LOG_MOD9,      
    LOG_MODA,     
    LOG_MODB,       
    LOG_MODC,   
    LOG_MODD, 
    LOG_MODE, 
    LOG_MODF, 
    LOG_MODG,  
    LOG_MODH,     
    LOG_MAX_MOD 
};

enum log_level
{
    LINF, 
    LWAR, 
    LERR,  
    LSCR   
};

extern FILE *g_pFile; /* Log fle handler */

int LOG_Init();
void LOG_Logging(int level, int module, char * format, ...);
void LOG_Close();

#endif

[ResidentBiscuit]

Your bottleneck is almost guaranteed to be filesystem access, so try to limit that. One method I've heard about is have all threads write their logs to some place in memory, and have one thread which periodically goes into memory and writes what's there to the filesystem. This way your threads are not waiting around for the filesystem to clear up, they can continue logging to memory.

[NoXzema]

There's also asynchronous event-based file IO which you can look into. I think you can use IOCP on windows but Linux/*BSD is relatively new to the concept.

http://bert-hubert.blogspot.com/2012/05/on-linux-asynchronous-file-io.html

I believe boost asio + boost filesystem is one way to go about things in an abstract way.

[Zhuge]

Boost actually just has a logging library if you want to use that.
http://www.boost.org/doc/libs/1_55_0/libs/log/doc/html/index.html
I believe it is thread-safe, but I don't know anything about its performance.

[myaegean]

About method using memory to buffer the logs:

If I let threads output their logs to memory, when assert generated(there are mass asserts in these threads), the program is terminated immediately the most important logs which are still in memory will be lost. How can I flush the logs buffered in memory to file before the program terminated. Can I accept/capture the signals generated by asserts of other threads?

[myaegean]

About Boost.log

I glanced over the boost website. It will be wise just using the existing library. I will investigate the feasibility.