From e63b7ee3855b1b0f2fb08196b0dd4cb80d14a8b9 Mon Sep 17 00:00:00 2001 From: dump2file Date: Mon, 18 Feb 2019 17:50:44 +0800 Subject: [PATCH] =?UTF-8?q?=E6=96=87=E4=BB=B6=E6=93=8D=E4=BD=9C=E9=80=BB?= =?UTF-8?q?=E8=BE=91=E5=8D=87=E7=BA=A7?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit #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 --- demo/test_handle_logger.c | 82 +++++++++++++++++++++++++++++++-------- src/MESA_handle_logger.c | 73 +++++++++++----------------------- src/Makefile | 7 +++- 3 files changed, 95 insertions(+), 67 deletions(-) diff --git a/demo/test_handle_logger.c b/demo/test_handle_logger.c index e5c4546..816d11c 100644 --- a/demo/test_handle_logger.c +++ b/demo/test_handle_logger.c @@ -4,25 +4,61 @@ #include #include #include +#include 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)); } diff --git a/src/MESA_handle_logger.c b/src/MESA_handle_logger.c index 49c393c..21e18e2 100644 --- 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; } diff --git a/src/Makefile b/src/Makefile index a7a913c..16fbe8c 100644 --- 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)