文件操作逻辑升级

#1 性能优化 1、句柄中存储文件句柄，无需每次打开 2、完善demo中的性能测试场景单机测试硬件（OS:CentOS Linux release 7.4.1708, CPU:Intel E5 2640 v4 2.4GHz, Disk:ST600MM0208 600G） 30线程每线程循环写入10w条日志，耗时380448us，平均日志写入速度788544条/s，日志平均长度104Byte/条，折合写入磁盘速度为78.8MB/s
2019-02-18 17:50:44 +08:00
parent 6c8af75e99
commit e63b7ee385
3 changed files with 95 additions and 67 deletions
--- a/demo/test_handle_logger.c
+++ b/demo/test_handle_logger.c
@@ -4,25 +4,61 @@
 #include <stdlib.h>
 #include <pthread.h>
 #include <signal.h>
+#include <time.h>

 void *sample_handle = NULL;
 void *test_handle = NULL;

-#define LOG_NUM 100
-#define THREAD_NUM 100
+#define LOG_NUM 100000
+#define MAX_THREAD_NUM 65535
+
+int g_log_num = 0;
+int g_thread_num = 0;
+volatile long g_start_time = 0;
+volatile long g_end_time = 0;

 void call_logger(int log_num, int thread_num)
 {
 		int i = 0;
+		struct timespec start, end;
+		long start_time, end_time, time_cost;
+		clock_gettime(CLOCK_MONOTONIC, &start);
+		start_time = start.tv_sec*1000000 + start.tv_nsec/1000;
+		if(g_start_time == 0)
+		{
+			g_start_time = start_time;
+		}	
+		else
+		{
+			if(g_start_time > start_time)
+			{
+				g_start_time = start_time;
+			}
+		}	
 		for(i = 0; i < log_num; i++)
 		{
 				MESA_handle_runtime_log(sample_handle, RLOG_LV_INFO, "sample", "sample_handle MESA_handle_runtime_log, i = %d, thread_num = %d", i, thread_num);
 				//sleep(1);
-				MESA_handle_runtime_log(test_handle, RLOG_LV_INFO, "test", "test_handle MESA_handle_runtime_log, i = %d, thread_num = %d", i, thread_num);
-				MESA_HANDLE_RUNTIME_LOG(sample_handle, RLOG_LV_FATAL, "sample", "sample_handle RUNTIEM_LOG test, i = %d, thread_num = %d", i, thread_num);
-				//sleep(1);
-				MESA_HANDLE_RUNTIME_LOG(test_handle, RLOG_LV_FATAL, "test", "test_handle RUNTIEM_LOG test, i = %d, thread_num = %d", i, thread_num);
+				//MESA_handle_runtime_log(test_handle, RLOG_LV_INFO, "test", "test_handle MESA_handle_runtime_log, i = %d, thread_num = %d", i, thread_num);
+				//MESA_HANDLE_RUNTIME_LOG(sample_handle, RLOG_LV_FATAL, "sample", "sample_handle RUNTIEM_LOG test, i = %d, thread_num = %d", i, thread_num);
+				////sleep(1);
+				//MESA_HANDLE_RUNTIME_LOG(test_handle, RLOG_LV_FATAL, "test", "test_handle RUNTIEM_LOG test, i = %d, thread_num = %d", i, thread_num);
 		}
+		clock_gettime(CLOCK_MONOTONIC, &end);
+		end_time = end.tv_sec*1000000 + end.tv_nsec/1000;
+		if(g_end_time == 0)
+		{
+			g_end_time = end_time;
+		}	
+		else
+		{
+			if(g_end_time < end_time)
+			{
+				g_end_time = end_time;
+			}
+		}	
+		time_cost = (end.tv_sec - start.tv_sec) * 1000000 + (end.tv_nsec - start.tv_nsec) / 1000 ;
+		printf("THREAD %d write %d log using %ld us, avg speed %f /s, %ld -> %ld\n", thread_num, log_num, time_cost, ((float)log_num/(float)time_cost)*1000000, start_time, end_time);
 		return;
 }

@@ -31,7 +67,7 @@ void *thread_logger(void *arg)
 {
 		int thread_num = (int)(unsigned long long)arg;
 		printf("thread %d created! \n", thread_num);
-		call_logger(LOG_NUM, thread_num);
+		call_logger(g_log_num, thread_num);
 		printf("thread %d finished! \n", thread_num);
 		return NULL;
 }
@@ -43,19 +79,33 @@ void sig_handler(int sig)
 		MESA_destroy_runtime_log_handle(test_handle);
 		sample_handle = NULL;
 		test_handle = NULL;
+		printf("%d thread write %d log using %ld us, avg speed %f /s, %ld -> %ld\n", g_thread_num, g_thread_num*g_log_num, g_end_time-g_start_time, ((float)(g_thread_num*g_log_num)/(float)(g_end_time-g_start_time))*1000000, g_start_time, g_end_time);
 		exit(0);
 }

-int main()
+int main(int argc, char ** args)
 {
-		pthread_t t[THREAD_NUM];
-		int i = 0;
+	pthread_t t[MAX_THREAD_NUM];
+	int i = 0;

-		sample_handle = MESA_create_runtime_log_handle("./log/test_log", RLOG_LV_DEBUG);	
-		if(sample_handle == NULL)
-		{
-				printf("get log sample_handle error\n");
-				return -1;
+	if(argc != 3)
+	{
+		printf("Usage: ./($app) $thread_num $log_num \n");
+		return -1;
+	}
+	g_thread_num = atoi(args[1]);
+	g_log_num = atoi(args[2]);
+
+	if(g_thread_num <= 0 || g_log_num <= 0)
+	{
+		printf("Error, wrong parameter!\n");
+		return -1;
+	}
+	sample_handle = MESA_create_runtime_log_handle("./log/test_log", RLOG_LV_DEBUG);
+	if (sample_handle == NULL)
+	{
+		printf("get log sample_handle error\n");
+		return -1;
 		}

 		test_handle = MESA_create_runtime_log_handle("./log/test_log", RLOG_LV_DEBUG);
@@ -65,7 +115,7 @@ int main()
 				return -1;
 		}

-		for(i = 0; i < THREAD_NUM; i++)
+		for(i = 0; i < g_thread_num; i++)
 		{	
 				pthread_create(&t[i], NULL, thread_logger, (void *)(unsigned long)(i));
 		}
--- a/src/MESA_handle_logger.c
+++ b/src/MESA_handle_logger.c
@@ -11,16 +11,13 @@
 typedef struct log_handle_t
 {
    int runtime_log_level;
+    FILE *fp;
    char runtime_log_file[1200];
 } log_handle_t;

-#define THREAD_CTIME(t, buf, len)       thread_safe_ctime(t, buf, len)
 #define LOGMSG_MAX_LEN      4096

-const int HANDLE_LOGGER_VERSION_20170816 = 1;
-
-static unsigned int month_days[12] =
-{31, 28, 31, 30, 31, 30, 31, 31, 30, 31, 30, 31};
+const int HANDLE_LOGGER_VERSION_20190218 = 1;

 static unsigned char weekday_str[7][4] =
 {"Sun", "Mon", "Tue", "Wed", "Thu", "Fri", "Sat"};
@@ -28,44 +25,6 @@ static unsigned char weekday_str[7][4] =
 static unsigned char month_str[12][4] = {"Jan", "Feb", "Mar", "Apr",
 	"May", "Jun", "Jul", "Aug", "Sep", "Oct", "Nov", "Dec"};

-char *thread_safe_ctime(const time_t *tp, char *buf, int len)
-{
-    unsigned int year, month, day, weekday, hour, min, sec;
-    unsigned int year_days = 365;
-    sec = * tp;
-    min = sec / 60; sec = sec % 60;
-    hour = min / 60; min = min % 60; hour += 8;
-    day = hour / 24; hour = hour % 24;
-    weekday = day % 7; weekday = (weekday + 4) % 7;
-
-    for(year = 1970; day >= year_days;)
-    {
-        day -= year_days;
-        year ++;
-
-        if(0 == year % 4 && (0 != year % 100 || 0 == year % 400))
-            year_days = 366;
-        else year_days = 365;
-    }
-
-    if(366 == year_days) month_days[1] = 29;
-
-	//bug fix by yw 20120808
-    for(month = 0; day >= month_days[month];)
-    {
-        day -= month_days[month];
-        month ++;
-    }
-
-    /*
-    snprintf(buf, len, "%02d:%02d:%02d, %04d/%02d/%02d, %s",
-        hour, min, sec, year, month, day, weekday_str[week_day]);
-    */
-    snprintf(buf, len, "%s %s %d %02d:%02d:%02d %d", weekday_str[weekday],
-             month_str[month], day + 1, hour, min, sec, year);
-    return buf;
-}
-
 static int create_dir(const char *dir_path, int path_len)
 {
    if(dir_path == NULL)
@@ -126,7 +85,7 @@ void *MESA_create_runtime_log_handle(const char *file_path, int level)
    if(NULL == (fp = fopen(file_path, "w")))
 		return NULL;

-    fclose(fp);
+    //fclose(fp);
    //remove(file_path);
    p_handle = (log_handle_t *)calloc(sizeof(log_handle_t), 1);

@@ -136,6 +95,7 @@ void *MESA_create_runtime_log_handle(const char *file_path, int level)
    strncpy(p_handle->runtime_log_file, file_path, 1024);
    p_handle->runtime_log_file[1024] = '\0';
    p_handle->runtime_log_level = level;
+    //p_handle->fp = fp;
    return (void *)p_handle;
 }

@@ -143,7 +103,13 @@ void MESA_destroy_runtime_log_handle(void *handle)
 {
    if(handle != NULL)
    {
-        free(handle);
+        log_handle_t *p_handle = (log_handle_t *)handle;
+        if (p_handle->fp != NULL)
+        {
+            fclose(p_handle->fp);
+            p_handle->fp = NULL;
+        }
+            free(handle);
        handle = NULL;
    }

@@ -158,7 +124,7 @@ void MESA_handle_runtime_log(void *handle, int level, const char *module, const
    va_list ap;
    FILE *fp;
    struct tm local_time;
-    char tmp_log_file_name[1201];
+    char tmp_log_file_name[1400];
    log_handle_t *p_handle = (log_handle_t *)handle;

    if(p_handle == NULL || p_handle->runtime_log_file == NULL)return;
@@ -167,7 +133,6 @@ void MESA_handle_runtime_log(void *handle, int level, const char *module, const

    time(&t);
    if(NULL == (localtime_r(&t, &local_time))) return;
-    //THREAD_CTIME(&t, buf, LOGMSG_MAX_LEN);
    len = snprintf(buf, sizeof(buf), "%s %s %d %02d:%02d:%02d %d", weekday_str[local_time.tm_wday],
             month_str[local_time.tm_mon], local_time.tm_mday, local_time.tm_hour, local_time.tm_min, local_time.tm_sec, local_time.tm_year+1900);
    //len = strlen(buf);
@@ -214,9 +179,17 @@ void MESA_handle_runtime_log(void *handle, int level, const char *module, const
            local_time.tm_year + 1900, local_time.tm_mon + 1,
            local_time.tm_mday);

-    if(NULL == (fp = fopen(tmp_log_file_name, "a"))) return;
+    if(p_handle->fp == NULL)
+    {
+        if(NULL == (fp = fopen(tmp_log_file_name, "a"))) return;

-    fprintf(fp, "%s", buf);
-    fclose(fp);
+        p_handle->fp = fp;
+    }
+    if (0 > fprintf(p_handle->fp, "%s", buf))
+    {
+        fclose(p_handle->fp);
+        p_handle->fp = NULL;
+    }
+    return;
 }

--- a/src/Makefile
+++ b/src/Makefile
@@ -3,6 +3,11 @@ VPATH=../inc
 CFLAGS= -g3 -Wall -fPIC -O -Werror
 CFLAGS+=-I../inc/

+ifdef ASAN
+CFLAGS_+= -fsanitize=address -fno-omit-frame-pointer 
+LIB+=-lasan
+endif
+
 SRC=MESA_handle_logger.c
 OBJS=$(SRC:.c=.o)

@@ -15,7 +20,7 @@ libMESA_handle_logger.a:$(OBJS)
 	ar cqs $@ $<

 libMESA_handle_logger.so:$(OBJS)
-	$(CC) $(CFLAGS) -shared $< -o $@
+	$(CC) $(CFLAGS) $(LIB) -shared $< -o $@
 .c.o:

 #$(OBJS):$(SRC)