✨ feat(clock_gettime): 使用CLOCK_MONOTONIC_COARSE

14 files changed, 158 insertions, 150 deletions

diff --git a/bin/etc/sapp.toml b/bin/etc/sapp.toml
index 41860b0..86fe371 100644
--- a/bin/etc/sapp.toml
+++ b/bin/etc/sapp.toml
@@ -185,6 +185,8 @@
     [profiling.process_latency]
     log_category="sapp_process_latency_log"
     histogram_enabled=0
+    local_file="fs2_process_latency.metrics"
+    refresh_interval_s=1
 ### note, threshold unit is microseconds (us)
     threshold_ms=10
 
diff --git a/include/private/sapp_declaration.h b/include/private/sapp_declaration.h
index 87ab557..7be6c63 100644
--- a/include/private/sapp_declaration.h
+++ b/include/private/sapp_declaration.h
@@ -56,6 +56,7 @@ extern volatile long long g_current_time_ms;
 #define ABBR_SYSINFO_LOG_DATA_FILE		sapp_global_val->config.data_file_path.data_sapp_sysinfo_log_absolute
 #define ABBR_FS2_LOG_DATA_FILE			sapp_global_val->config.data_file_path.data_sapp_fs2_log_absolute
 #define ABBR_FS3_LOG_DATA_FILE			sapp_global_val->config.data_file_path.data_sapp_fs3_log_absolute
+#define ABBR_PROCESS_LATENTCY_DATA_FILE			sapp_global_val->config.data_file_path.data_sapp_fs2_process_latency_absolute
 #define ABBR_INLINE_KEEPALIVE_LOG_DATA_FILE  sapp_global_val->config.data_file_path.data_inline_keepalive_log_absolute
 #define ABBR_LOAD_PLUG_STAT_LOG_DATA_FILE  sapp_global_val->config.data_file_path.data_load_plugin_stat_log_absolute
 #define ABBR_MARSIO_LIBRARY_FILE  	sapp_global_val->config.library_file_path.libmarsio_file_path
diff --git a/include/private/sapp_global_val.h b/include/private/sapp_global_val.h
index 45aaf9c..8926c75 100644
--- a/include/private/sapp_global_val.h
+++ b/include/private/sapp_global_val.h
@@ -149,6 +149,8 @@ typedef struct{
 	//process_latency and sanity_check
 	char process_latency_log_category[NAME_MAX];
 	int histogram_enabled;
+	char process_latency_local_file[NAME_MAX];
+	int process_latency_refresh_interval_s;
 	int process_latency_threshold_in_ms; /* nanosecond, �����ļ��ﵥλ��microsecond, ��Ҫ����1000 */
 	/* ��ȷģʽ������, fs2����ͳ��Ҳ�dz���CPU, ÿ������Ҫ����FS_operate(),
 	   ���ͣ�þ�ȷģʽ, ����fs2���DZ������һ��ʱ������ֵ, ��Сֵ����һ��ʱ���ƽ��ֵ, ������FS_operate()����,
@@ -312,6 +314,9 @@ typedef struct{
 	const char *data_sapp_fs3_log_relative;
 	const char *data_sapp_fs3_log_absolute;
 
+	const char *data_sapp_fs2_process_latency_relative;
+	const char *data_sapp_fs2_process_latency_absolute;
+
 	const char *data_inline_keepalive_log_relative;
 	const char *data_inline_keepalive_log_absolute;	
 
@@ -358,6 +363,8 @@ typedef struct{
 	void *fs_metric_handle; 
 	int fs_id_count_array[SAPP_STAT_NUM_MAX];
 	int fs_id_length_array[SAPP_STAT_NUM_MAX];
+
+	void *fs_process_lantency_handle; 
 	int fs_latency_id_array[SAPP_MAX_THREADS];
 	int fs_latency_plug_entrg_id_array[SAPP_MAX_PLUG_ENTRY_NUM];
 	int fs_work_percent_id_array[SAPP_MAX_THREADS];
diff --git a/src/config/cmd_args.c b/src/config/cmd_args.c
index f9d83f0..aedd546 100644
--- a/src/config/cmd_args.c
+++ b/src/config/cmd_args.c
@@ -421,6 +421,7 @@ void sapp_update_data_root_dir(const char *data_root_dir)
 	sapp_convert_relative_to_absolute(pdata->data_sapp_sysinfo_log_relative, (char **)&pdata->data_sapp_sysinfo_log_absolute, pdata->data_files_root_dir);
 	sapp_convert_relative_to_absolute(pdata->data_sapp_fs2_log_relative, (char **)&pdata->data_sapp_fs2_log_absolute, pdata->data_files_root_dir);
 	sapp_convert_relative_to_absolute(pdata->data_sapp_fs3_log_relative, (char **)&pdata->data_sapp_fs3_log_absolute, pdata->data_files_root_dir);
+	sapp_convert_relative_to_absolute(pdata->data_sapp_fs2_process_latency_relative, (char **)&pdata->data_sapp_fs2_process_latency_absolute, pdata->data_files_root_dir);
 	sapp_convert_relative_to_absolute(pdata->data_inline_keepalive_log_relative, (char **)&pdata->data_inline_keepalive_log_absolute, pdata->data_files_root_dir);	
 	sapp_convert_relative_to_absolute(pdata->data_load_plugin_stat_log_relative, (char **)&pdata->data_load_plugin_stat_log_absolute, pdata->data_files_root_dir);	
 	sapp_convert_relative_to_absolute(pdata->data_under_ddos_stat_log_relative, (char **)&pdata->data_under_ddos_stat_log_absolute, pdata->data_files_root_dir);	
diff --git a/src/config/config_parse.cpp b/src/config/config_parse.cpp
index bfb311e..c6e1604 100644
--- a/src/config/config_parse.cpp
+++ b/src/config/config_parse.cpp
@@ -1470,6 +1470,17 @@ int sapp_get_secondary_file_path(void)
 		}
 		pconfig->data_file_path.data_sapp_fs3_log_relative = sapp_strdup(pconfig->profiling.fs3.local_file);
 	}
+
+	tomlc99_wrap_load_string_def(ABBR_CFG_FILE_MAIN_ENTRY, (char *)"profiling.process_latency", (char *)"local_file", pconfig->profiling.process_latency_local_file, NAME_MAX, "");
+	if (strlen(pconfig->profiling.process_latency_local_file) > 0)
+	{
+		if (pconfig->data_file_path.data_sapp_fs2_process_latency_relative)
+		{
+			SAPP_GLOBAL_FREE(pconfig->data_file_path.data_sapp_fs2_process_latency_relative);
+		}
+		pconfig->data_file_path.data_sapp_fs2_process_latency_relative = sapp_strdup(pconfig->profiling.process_latency_local_file);
+	}
+
 	/*************************** SECONDARY_CONFIG_LINK *************************/
 	tomlc99_wrap_load_string_def(ABBR_CFG_FILE_MAIN_ENTRY, (char *)"SECONDARY_CONFIG_LINK", (char *)"cfg_file_sapp_log", str_tmp, ARG_MAX, "etc/sapp_log.conf");
 	if(str_tmp[0] != '\0'){
diff --git a/src/dealpkt/callapp.c b/src/dealpkt/callapp.c
index 5cc2462..6862515 100644
--- a/src/dealpkt/callapp.c
+++ b/src/dealpkt/callapp.c
@@ -286,23 +286,13 @@ char plugin_call_streamentry(int type,StreamFunInfo *pFunInfo,struct streaminfo
 	long long time_spent_ns;

 	char debug_raw_pkt_string[256];

 	struct streaminfo_private *pstream_pr=(struct streaminfo_private *)a_stream;

-	long long timestamp_begin_ms, timestamp_end_ms, time_spend_ms;

 	const struct streaminfo_private *stream_pr ;

-#if SAPP_INSECTICIDE

-	const struct streaminfo_private *stream_pr = (const struct streaminfo_private *)a_stream;

-	if(a_packet != NULL){

-		assert(stream_pr->raw_pkt->io_lib_pkt_reference);

-		assert(RAW_PKT_MAGIC_NUM == stream_pr->raw_pkt->magic_num);

-	}

-#endif

-	if(unlikely(sapp_global_val->config.profiling.histogram_enabled)){

-		clock_gettime(CLOCK_REALTIME, &before_ts);

-	}

-	else

+

+	int latency_enabled=MESA_handle_runtime_log_level_enabled(ABBR_PROCESS_LATENCY_LOG_HANDLE, RLOG_LV_INFO);

+	if(unlikely(latency_enabled))

 	{

-		timestamp_begin_ms=ABBR_CURRENT_TIME_MS;

+		clock_gettime(CLOCK_MONOTONIC_COARSE, &before_ts);

 	}

-

 	if(type==CALL_FUN_TYPE_RAW)

 	{

 		pstream_pr->cur_plugin_cb_func = (void *)pFunInfo;

@@ -314,57 +304,29 @@ char plugin_call_streamentry(int type,StreamFunInfo *pFunInfo,struct streaminfo
 		rec=((STREAM_CB_FUN_T)pFunInfo->pfun)(a_stream,&(pFunInfo->pAppInfo),thread_seq, a_packet);

 	}

 

-	if(unlikely(sapp_global_val->config.profiling.histogram_enabled)){

-		clock_gettime(CLOCK_REALTIME, &after_ts);

+	if(unlikely(latency_enabled)){

+		clock_gettime(CLOCK_MONOTONIC_COARSE, &after_ts);

 		time_spent_ns = (after_ts.tv_sec * 1000000000 + after_ts.tv_nsec) - (before_ts.tv_sec * 1000000000 + before_ts.tv_nsec);

-		sapp_fs2_fuzzy_latency_update_per_entry(thread_seq, pFunInfo->entry_id, time_spent_ns);

+		if(sapp_global_val->config.profiling.histogram_enabled && time_spent_ns > 0)

+		{

+			sapp_fs2_fuzzy_latency_update_per_entry(thread_seq, pFunInfo->entry_id, time_spent_ns);

+		}

 		if(unlikely(time_spent_ns >= g_timestamp_record_threshold*1000000)){

 			if(NULL == a_packet || OP_STATE_CLOSE == a_stream->opstate || OP_STATE_CLOSE == a_stream->pktstate){

-				sapp_process_latency_log(RLOG_LV_FATAL, "plug_name:%s, entry:%s, stream close process latency:%lld ns, addr:%s, thread_seq:%d", 

+				sapp_process_latency_log(RLOG_LV_INFO, "plug_name:%s, entry:%s, stream close process latency:%lld ns, addr:%s, thread_seq:%d", 

 								g_plug_global_entry[pFunInfo->entry_id].plug_name, 

 								g_plug_global_entry[pFunInfo->entry_id].plug_entry_name, time_spent_ns,

 								printaddr(&a_stream->addr, thread_seq), thread_seq);

 			}else{

 				stream_pr = (struct streaminfo_private *)a_stream;

 				sapp_rawpkt_ntop(stream_pr->raw_pkt, 1, debug_raw_pkt_string, sizeof(debug_raw_pkt_string)); /* �˴����ȴ�ӡ���ڲ���Ԫ�� */

-				sapp_process_latency_log(RLOG_LV_FATAL, "plug_name:%s, entry:%s, pkt process latency:%lld ns, rawpkt:%s, thread:%s", 

+				sapp_process_latency_log(RLOG_LV_INFO, "plug_name:%s, entry:%s, pkt process latency:%lld ns, rawpkt:%s, thread:%d", 

 								g_plug_global_entry[pFunInfo->entry_id].plug_name, 

 								g_plug_global_entry[pFunInfo->entry_id].plug_entry_name, 

 								time_spent_ns, debug_raw_pkt_string, thread_seq);

 			}

 		}		

 	}	

-	else

-	{

-		timestamp_end_ms=ABBR_CURRENT_TIME_MS;

-		time_spend_ms=timestamp_end_ms-timestamp_begin_ms;

-		if (unlikely(time_spend_ms > 0 && time_spend_ms >= g_timestamp_record_threshold))

-		{

-			if (NULL == a_packet || OP_STATE_CLOSE == a_stream->opstate || OP_STATE_CLOSE == a_stream->pktstate)

-			{

-				sapp_process_latency_log(RLOG_LV_FATAL, "plug_name:%s, entry:%s, stream close process latency:%lld ms, %s",

-										 g_plug_global_entry[pFunInfo->entry_id].plug_name,

-										 g_plug_global_entry[pFunInfo->entry_id].plug_entry_name, time_spend_ms,

-										 printaddr(&a_stream->addr, thread_seq));

-			}

-			else

-			{

-				stream_pr = (struct streaminfo_private *)a_stream;

-				sapp_rawpkt_ntop(stream_pr->raw_pkt, 1, debug_raw_pkt_string, sizeof(debug_raw_pkt_string)); /* �˴����ȴ�ӡ���ڲ���Ԫ�� */

-				sapp_process_latency_log(RLOG_LV_FATAL, "plug_name:%s, entry:%s, pkt process latency:%lld ms, %s",

-										 g_plug_global_entry[pFunInfo->entry_id].plug_name,

-										 g_plug_global_entry[pFunInfo->entry_id].plug_entry_name,

-										 time_spend_ms, debug_raw_pkt_string);

-			}

-		}

-	}

-

-#if SAPP_INSECTICIDE

-	if(a_packet != NULL){

-		assert(stream_pr->raw_pkt->io_lib_pkt_reference);

-		assert(RAW_PKT_MAGIC_NUM == stream_pr->raw_pkt->magic_num);

-	}

-#endif

 	return rec;

 }

 

diff --git a/src/dealpkt/deal_l2tp.c b/src/dealpkt/deal_l2tp.c
index b8ac517..b1f8138 100644
--- a/src/dealpkt/deal_l2tp.c
+++ b/src/dealpkt/deal_l2tp.c
@@ -488,7 +488,7 @@ static int guess_if_l2tpv2(const struct streaminfo *a_udp, const struct mesa_udp
 				return 0;

 			}

 		}else{

-			sapp_runtime_log(RLOG_LV_INFO, "stream:%s, maybe L2TP packet, but next layer:%u not ipv4 or ipv6!\n", *next_ip_hdr, printaddr(&a_udp->addr, a_udp->threadnum));

+			sapp_runtime_log(RLOG_LV_INFO, "stream:%s, maybe L2TP packet, but next layer:%u not ipv4 or ipv6!\n",printaddr(&a_udp->addr, a_udp->threadnum),  *next_ip_hdr);

 			return 0;

 		}

 	}

diff --git a/src/extensions/sapp_metrics.cpp b/src/extensions/sapp_metrics.cpp
index d2432e4..e6beb5c 100644
--- a/src/extensions/sapp_metrics.cpp
+++ b/src/extensions/sapp_metrics.cpp
@@ -24,8 +24,8 @@ void sapp_fs2_update_length(int field_index, unsigned  long long value)
 
 void sapp_fs2_set_work_percent(int thead_seq, long long work_percent)
 {
-    if(sapp_global_val->individual_fixed.fs2_runtime.fs_metric_handle != NULL){
-        FS_operate(sapp_global_val->individual_fixed.fs2_runtime.fs_metric_handle, 
+    if(sapp_global_val->individual_fixed.fs2_runtime.fs_process_lantency_handle != NULL){
+        FS_operate(sapp_global_val->individual_fixed.fs2_runtime.fs_process_lantency_handle, 
         		   sapp_global_val->individual_fixed.fs2_runtime.fs_work_percent_id_array[thead_seq], 
         		   0, FS_OP_SET, work_percent);
     }
@@ -33,8 +33,8 @@ void sapp_fs2_set_work_percent(int thead_seq, long long work_percent)
 
 void sapp_fs2_set_latency(int thead_seq, long long time_cost)
 {
-    if(sapp_global_val->individual_fixed.fs2_runtime.fs_metric_handle != NULL){
-        FS_operate(sapp_global_val->individual_fixed.fs2_runtime.fs_metric_handle, 
+    if(sapp_global_val->individual_fixed.fs2_runtime.fs_process_lantency_handle != NULL){
+        FS_operate(sapp_global_val->individual_fixed.fs2_runtime.fs_process_lantency_handle, 
         		   sapp_global_val->individual_fixed.fs2_runtime.fs_latency_id_array[thead_seq], 
         		   0, FS_OP_SET, time_cost);
     }
@@ -47,8 +47,8 @@ void sapp_fs2_set_plug_entry_latency(int entry_id, long long time_cost)
 	if(unlikely(entry_id < 0 || entry_id >= SAPP_MAX_PLUG_ENTRY_NUM)){
 		return;
 	}
-    if(sapp_global_val->individual_fixed.fs2_runtime.fs_metric_handle != NULL){
-        FS_operate(sapp_global_val->individual_fixed.fs2_runtime.fs_metric_handle, 
+    if(sapp_global_val->individual_fixed.fs2_runtime.fs_process_lantency_handle != NULL){
+        FS_operate(sapp_global_val->individual_fixed.fs2_runtime.fs_process_lantency_handle, 
         		   sapp_global_val->individual_fixed.fs2_runtime.fs_latency_plug_entrg_id_array[entry_id], 
         		   0, FS_OP_SET, time_cost);
     }
@@ -142,6 +142,78 @@ void sapp_fuzzy_latency_update(void)
 	}
 }
 
+static int sapp_process_latency_metric_init(sapp_global_t *global_paramters)
+{
+	void *fs2_handle=NULL;
+	int fs2_opt;
+	sapp_gval_individual_fixed_fs2_t *p_fs2_rt = &global_paramters->individual_fixed.fs2_runtime;
+	if(strlen(global_paramters->config.profiling.process_latency_local_file) == 0)
+	{
+			return -1;
+	}
+	p_fs2_rt->fs_process_lantency_handle = FS_create_handle();
+	if (NULL == p_fs2_rt->fs_process_lantency_handle)
+	{
+			sapp_log(RLOG_LV_FATAL, 30, 30, "FS_create_handle() error: %s!\n", strerror(errno));
+			return -1;
+	}
+	fs2_handle = p_fs2_rt->fs_process_lantency_handle;
+	FS_set_para(fs2_handle, STAT_CYCLE, &global_paramters->config.profiling.process_latency_refresh_interval_s, sizeof(int));
+
+	fs2_opt = 1; /* 1:Rewrite ,2: Append.  */
+	FS_set_para(fs2_handle, PRINT_MODE, &fs2_opt, sizeof(int));
+
+	fs2_opt = 1;
+	FS_set_para(fs2_handle, PRINT_TRIGGER, &fs2_opt, sizeof(int));
+
+	fs2_opt = 1;
+    FS_set_para(fs2_handle, NOT_SEND_METRIC_TO_SERVER, &fs2_opt, sizeof(int));	
+	FS_set_para(fs2_handle, OUTPUT_DEVICE, ABBR_PROCESS_LATENTCY_DATA_FILE, strlen(ABBR_PROCESS_LATENTCY_DATA_FILE) + 1);
+
+	for (int i = 0; i < g_packet_io_thread_num; i++)
+	{
+			char histogram_name[16];
+			sprintf(histogram_name, "TD_ns(tid_%d)", i);
+			p_fs2_rt->fs_latency_id_array[i] = FS_register_histogram(fs2_handle,	 // Field Stat���
+																	 FS_CALC_SPEED,	 // ����ۼ�ֵ��˲ʱֵ
+																	 histogram_name, // ͳ�������ƣ��ַ���
+																	 1,				 // ��׷�ٵ���Сֵ
+																	 1000000,		 // ��׷�ٵ����ֵ
+																	 2);			 // ���ȣ���С�����λ����Χ1~4
+			FS_set_para(fs2_handle, NOT_SEND_METRIC_TO_SERVER, &p_fs2_rt->fs_latency_id_array[i], sizeof(int));
+	}
+
+	/* 0������sapp���ò��, index��1��ʼ */
+	for (int i = 1; i < g_plug_global_entry_index; i++)
+	{
+			p_fs2_rt->fs_latency_plug_entrg_id_array[i] = FS_register_histogram(p_fs2_rt->fs_metric_handle,				// Field Stat���
+																				FS_CALC_SPEED,							// ����ۼ�ֵ��˲ʱֵ
+																				g_plug_global_entry[i].plug_entry_name, // ͳ�������ƣ��ַ���
+																				1,										// ��׷�ٵ���Сֵ
+																				1000000,								// ��׷�ٵ����ֵ
+																				2);										// ���ȣ���С�����λ����Χ1~4
+			if (p_fs2_rt->fs_latency_plug_entrg_id_array[i] < 0)
+			{
+			sapp_runtime_log(RLOG_LV_FATAL, "FS_register_histogram() error, plug name:%s", g_plug_global_entry[i].plug_entry_name);
+			return -1;
+			}
+	}
+
+	for (int i = 0; i < g_packet_io_thread_num; i++)
+	{
+		char histogram_name[16];
+		sprintf(histogram_name, "Work(tid_%d)", i);
+		p_fs2_rt->fs_work_percent_id_array[i] = FS_register_histogram(fs2_handle,	 // Field Stat���
+																 FS_CALC_SPEED,	 // ����ۼ�ֵ��˲ʱֵ
+																 histogram_name, // ͳ�������ƣ��ַ���
+																 1,				 // ��׷�ٵ���Сֵ
+																 100,		 // ��׷�ٵ����ֵ
+																 1);			 // ���ȣ���С�����λ����Χ1~4
+		FS_set_para(fs2_handle, NOT_SEND_METRIC_TO_SERVER, &p_fs2_rt->fs_work_percent_id_array[i], sizeof(int));
+	}
+	return 0;
+}
+
 /************************ C++ compiler **************************************/
 static int sapp_fs2_init(sapp_global_t *global_paramters)
 {
@@ -321,49 +393,6 @@ static int sapp_fs2_start(sapp_global_t *global_paramters)
 {
 	sapp_gval_individual_fixed_fs2_t *p_fs2_rt = &global_paramters->individual_fixed.fs2_runtime;
 	void *fs2_handle = p_fs2_rt->fs_metric_handle;
-	if (unlikely(sapp_global_val->config.profiling.histogram_enabled))
-	{
-		for (int i = 0; i < g_packet_io_thread_num; i++)
-		{
-			char histogram_name[16];
-			sprintf(histogram_name, "TD_ns(tid_%d)", i);
-			p_fs2_rt->fs_latency_id_array[i] = FS_register_histogram(fs2_handle,	 // Field Stat���
-																	 FS_CALC_SPEED,	 // ����ۼ�ֵ��˲ʱֵ
-																	 histogram_name, // ͳ�������ƣ��ַ���
-																	 1,				 // ��׷�ٵ���Сֵ
-																	 1000000,		 // ��׷�ٵ����ֵ
-																	 2);			 // ���ȣ���С�����λ����Χ1~4
-			FS_set_para(fs2_handle, NOT_SEND_METRIC_TO_SERVER, &p_fs2_rt->fs_latency_id_array[i], sizeof(int));
-		}
-
-		/* 0������sapp���ò��, index��1��ʼ */
-		for (int i = 1; i < g_plug_global_entry_index; i++)
-		{
-			p_fs2_rt->fs_latency_plug_entrg_id_array[i] = FS_register_histogram(p_fs2_rt->fs_metric_handle,				// Field Stat���
-																				FS_CALC_SPEED,							// ����ۼ�ֵ��˲ʱֵ
-																				g_plug_global_entry[i].plug_entry_name, // ͳ�������ƣ��ַ���
-																				1,										// ��׷�ٵ���Сֵ
-																				1000000,								// ��׷�ٵ����ֵ
-																				2);										// ���ȣ���С�����λ����Χ1~4
-			if (p_fs2_rt->fs_latency_plug_entrg_id_array[i] < 0)
-			{
-				sapp_runtime_log(RLOG_LV_FATAL, "FS_register_histogram() error, plug name:%s", g_plug_global_entry[i].plug_entry_name);
-				return -1;
-			}
-		}
-	}
-	for (int i = 0; i < g_packet_io_thread_num; i++)
-	{
-		char histogram_name[16];
-		sprintf(histogram_name, "Work(tid_%d)", i);
-		p_fs2_rt->fs_work_percent_id_array[i] = FS_register_histogram(fs2_handle,	 // Field Stat���
-																 FS_CALC_SPEED,	 // ����ۼ�ֵ��˲ʱֵ
-																 histogram_name, // ͳ�������ƣ��ַ���
-																 1,				 // ��׷�ٵ���Сֵ
-																 100,		 // ��׷�ٵ����ֵ
-																 1);			 // ���ȣ���С�����λ����Χ1~4
-		FS_set_para(fs2_handle, NOT_SEND_METRIC_TO_SERVER, &p_fs2_rt->fs_work_percent_id_array[i], sizeof(int));
-	}
 	FS_start(fs2_handle);
 	return 0;
 }
@@ -616,6 +645,10 @@ int sapp_metric_init(void)
 	{
 		sapp_fs3_init(sapp_global_val);
 	}
+	if( sapp_global_val->config.profiling.histogram_enabled == 1)
+	{
+		sapp_process_latency_metric_init(sapp_global_val);
+	}
 	
 	return ret;
 }
@@ -631,6 +664,13 @@ int sapp_metric_start(void)
 	{
 		sapp_fs3_start(sapp_global_val);
 	}
+	if( sapp_global_val->config.profiling.histogram_enabled == 1)
+	{
+		if(sapp_global_val->individual_fixed.fs2_runtime.fs_process_lantency_handle)
+		{
+			FS_start(sapp_global_val->individual_fixed.fs2_runtime.fs_process_lantency_handle);
+		}
+	}
 	return ret;
 }
 
@@ -645,4 +685,11 @@ void sapp_metric_destroy(void)
 	{
 		sapp_fs3_destroy(sapp_global_val);
 	}
+	if( sapp_global_val->config.profiling.histogram_enabled == 1)
+	{
+		if (sapp_global_val->individual_fixed.fs2_runtime.fs_process_lantency_handle)
+		{
+			FS_stop(&sapp_global_val->individual_fixed.fs2_runtime.fs_process_lantency_handle);
+		}
+	}
 }
diff --git a/src/packet_io/packet_io.c b/src/packet_io/packet_io.c
index 6898bd2..42af21b 100644
--- a/src/packet_io/packet_io.c
+++ b/src/packet_io/packet_io.c
@@ -624,9 +624,10 @@ static int mesa_default_pkt_cb(const raw_pkt_t *p_raw_pkt, unsigned char dir, in
 		local_sys_stat->length[SAPP_STAT_RAW_OUTBOUND] += ((unsigned long long)p_raw_pkt->raw_pkt_len - p_raw_pkt->overlay_layer_bytes);
 	}
 
-	if(unlikely(sapp_global_val->config.profiling.histogram_enabled))
+	int latency_enabled=MESA_handle_runtime_log_level_enabled(ABBR_PROCESS_LATENCY_LOG_HANDLE, RLOG_LV_INFO);
+	if(unlikely(latency_enabled))
 	{
-		clock_gettime(CLOCK_MONOTONIC, &start);
+		clock_gettime(CLOCK_MONOTONIC_COARSE, &start);
 		//before_call = sapp_get_cpu_cycle();
 	}
 #if DEBUG
@@ -666,15 +667,15 @@ static int mesa_default_pkt_cb(const raw_pkt_t *p_raw_pkt, unsigned char dir, in
 		}
 	}
 
-	//after_call = sapp_get_cpu_cycle();
-	//timecost = after_call - before_call;
-	if(unlikely(sapp_global_val->config.profiling.histogram_enabled))
+	if(unlikely(latency_enabled))
     {
-		clock_gettime(CLOCK_MONOTONIC, &end);
+		clock_gettime(CLOCK_MONOTONIC_COARSE, &end);
     	timecost = (end.tv_sec*1000000000 +end.tv_nsec) - (start.tv_sec * 1000000000 + start.tv_nsec);
 
-		//timestamp_region_update(thread_num,  timecost);
-		sapp_fs2_fuzzy_latency_update_per_thread(thread_num,  timecost);
+		if(sapp_global_val->config.profiling.histogram_enabled)
+		{
+			sapp_fs2_fuzzy_latency_update_per_thread(thread_num,  timecost);
+		}
 	}
 
 	if(g_platform_action_cb_fun != NULL){
diff --git a/src/plugin/src/plugin.c b/src/plugin/src/plugin.c
index 79b40ca..fe03b79 100644
--- a/src/plugin/src/plugin.c
+++ b/src/plugin/src/plugin.c
@@ -143,13 +143,13 @@ int g_plugin_version_VERSION_20170511;
 
 static inline void __plug_record_time_start(struct timespec *start)
 {
-    clock_gettime(CLOCK_MONOTONIC, start);
+    clock_gettime(CLOCK_MONOTONIC_COARSE, start);
 }
 static inline long __plug_record_time_elapse_us(struct timespec *start)
 {
     struct timespec end;
     long elapsed = 0;
-    clock_gettime(CLOCK_MONOTONIC, &end);
+    clock_gettime(CLOCK_MONOTONIC_COARSE, &end);
     elapsed = (end.tv_sec - start->tv_sec)*1000000 + (end.tv_nsec - start->tv_nsec)/1000;
     return elapsed;
 }
@@ -1244,33 +1244,30 @@ char plugin_call_appentry(stSessionFunInfo* funelem_session,stSessionInfo* sessi
 	struct timespec before_ts, after_ts;
 	long long time_spent_ns;
 	char debug_raw_pkt_string[256];
-	long long timestamp_begin_ms, timestamp_end_ms, time_spend_ms;
 	const struct streaminfo_private *stream_pr ;
 
 	if(g_business_plug_info==NULL)
 	{
 		return rec;
 	}
-	if(unlikely(sapp_global_val->config.profiling.histogram_enabled)){
-		//plug_record_start_time(g_business_plug_info->plugid, thread_seq);
-		clock_gettime(CLOCK_REALTIME, &before_ts);
-	}
-	else
+	int latency_enabled=MESA_handle_runtime_log_level_enabled(ABBR_PROCESS_LATENCY_LOG_HANDLE, RLOG_LV_INFO);
+	if(unlikely(latency_enabled))
 	{
-		timestamp_begin_ms=ABBR_CURRENT_TIME_MS;
+		clock_gettime(CLOCK_MONOTONIC_COARSE, &before_ts);
 	}
 
 	rec=funelem_session->appentry(session_info,&(funelem_session->pme),thread_seq,a_stream,a_packet);
 
-	//plug_record_end_time(g_business_plug_info->plugid, thread_seq);
-	if(unlikely(sapp_global_val->config.profiling.histogram_enabled)){
-		//plug_record_start_time(g_business_plug_info->plugid, thread_seq);
-		clock_gettime(CLOCK_REALTIME, &after_ts);
+	if(unlikely(latency_enabled)){
+		clock_gettime(CLOCK_MONOTONIC_COARSE, &after_ts);
 		time_spent_ns = (after_ts.tv_sec*1000000000 + after_ts.tv_nsec) - (before_ts.tv_sec*1000000000 + before_ts.tv_nsec);
-		sapp_fs2_fuzzy_latency_update_per_entry(thread_seq, funelem_session->entry_id, time_spent_ns);
+		if(sapp_global_val->config.profiling.histogram_enabled && time_spent_ns > 0)
+		{
+			sapp_fs2_fuzzy_latency_update_per_entry(thread_seq, funelem_session->entry_id, time_spent_ns);
+		}
 		if(time_spent_ns >= g_timestamp_record_threshold*1000000){
 			if(NULL == a_packet || (SESSION_STATE_CLOSE & session_info->session_state)){
-				sapp_process_latency_log(RLOG_LV_FATAL, "plug_name:%s, entry:%s, session close process latency:%lld ns, addr:%s, thread:%d", 
+				sapp_process_latency_log(RLOG_LV_INFO, "plug_name:%s, entry:%s, session close process latency:%lld ns, addr:%s, thread:%d", 
 								g_plug_global_entry[funelem_session->entry_id].plug_name, 
 								g_plug_global_entry[funelem_session->entry_id].plug_entry_name, time_spent_ns,
 								printaddr(&a_stream->addr, thread_seq), thread_seq);
@@ -1278,36 +1275,13 @@ char plugin_call_appentry(stSessionFunInfo* funelem_session,stSessionInfo* sessi
 			}else{
 				stream_pr = (struct streaminfo_private *)a_stream;
 				sapp_rawpkt_ntop(stream_pr->raw_pkt, 1, debug_raw_pkt_string, sizeof(debug_raw_pkt_string));
-				sapp_process_latency_log(RLOG_LV_FATAL, "plug_name:%s, entry:%s, pkt process latency:%lld ns, rawpkt:%s, thread:%d", 
+				sapp_process_latency_log(RLOG_LV_INFO, "plug_name:%s, entry:%s, pkt process latency:%lld ns, rawpkt:%s, thread:%d", 
 								g_plug_global_entry[funelem_session->entry_id].plug_name, 
 								g_plug_global_entry[funelem_session->entry_id].plug_entry_name, 
 								time_spent_ns,debug_raw_pkt_string, thread_seq);
 			}				
 		}
 	}	
-	else
-	{
-		timestamp_end_ms=ABBR_CURRENT_TIME_MS;
-		time_spend_ms=timestamp_end_ms-timestamp_begin_ms;
-		if (unlikely(time_spend_ms > 0 && time_spend_ms >= g_timestamp_record_threshold))
-		{
-			if(NULL == a_packet || (SESSION_STATE_CLOSE & session_info->session_state)){
-				sapp_process_latency_log(RLOG_LV_FATAL, "plug_name:%s, entry:%s, session close process latency:%lld ns, addr:%s, thread:%d", 
-								g_plug_global_entry[funelem_session->entry_id].plug_name, 
-								g_plug_global_entry[funelem_session->entry_id].plug_entry_name, time_spent_ns,
-								printaddr(&a_stream->addr, thread_seq), thread_seq);
-
-			}else{
-				stream_pr = (struct streaminfo_private *)a_stream;
-				sapp_rawpkt_ntop(stream_pr->raw_pkt, 1, debug_raw_pkt_string, sizeof(debug_raw_pkt_string));
-				sapp_process_latency_log(RLOG_LV_FATAL, "plug_name:%s, entry:%s, pkt process latency:%lld ns, rawpkt:%s, thread:%d", 
-								g_plug_global_entry[funelem_session->entry_id].plug_name, 
-								g_plug_global_entry[funelem_session->entry_id].plug_entry_name, 
-								time_spent_ns,debug_raw_pkt_string, thread_seq);
-			}		
-		}
-	}
-
 	return rec;
 }
 
diff --git a/src/sapp_dev/sapp_global_val.c b/src/sapp_dev/sapp_global_val.c
index 164c255..b2e5959 100644
--- a/src/sapp_dev/sapp_global_val.c
+++ b/src/sapp_dev/sapp_global_val.c
@@ -316,6 +316,8 @@ void sapp_gval_destroy(void)
 	SAPP_GLOBAL_FREE(pdata->data_sapp_fs2_log_absolute);
 	SAPP_GLOBAL_FREE(pdata->data_sapp_fs3_log_relative);
 	SAPP_GLOBAL_FREE(pdata->data_sapp_fs3_log_absolute);
+	SAPP_GLOBAL_FREE(pdata->data_sapp_fs2_process_latency_absolute);
+	SAPP_GLOBAL_FREE(pdata->data_sapp_fs2_process_latency_relative);
 	SAPP_GLOBAL_FREE(pdata->data_inline_keepalive_log_relative);
 	SAPP_GLOBAL_FREE(pdata->data_inline_keepalive_log_absolute);
 	SAPP_GLOBAL_FREE(pdata->data_load_plugin_stat_log_relative);
diff --git a/src/support/cpu_limit/cpu_limit.c b/src/support/cpu_limit/cpu_limit.c
index 8ffd13d..7b6fa9f 100644
--- a/src/support/cpu_limit/cpu_limit.c
+++ b/src/support/cpu_limit/cpu_limit.c
@@ -418,7 +418,7 @@ static inline long long _cl_get_current_time_in_ms(void)
 	//gettimeofday(&t, NULL);
 	//tms = t.tv_sec * 1000 + t.tv_usec/1000;
 	struct timespec t;
-    clock_gettime(CLOCK_REALTIME, &t);
+    clock_gettime(CLOCK_MONOTONIC_COARSE, &t);
     tms = (t.tv_sec)*1000 + (t.tv_nsec)/(1000*1000);
 
 	return tms;
diff --git a/src/timer/sapp_timer.c b/src/timer/sapp_timer.c
index aa29879..713da23 100644
--- a/src/timer/sapp_timer.c
+++ b/src/timer/sapp_timer.c
@@ -403,7 +403,7 @@ static inline long long sapp_get_current_time_in_ms(void)
 	//gettimeofday(&t, NULL);
 	//tms = t.tv_sec * 1000 + t.tv_usec/1000;
 	struct timespec t;
-    clock_gettime(CLOCK_REALTIME, &t);
+    clock_gettime(CLOCK_MONOTONIC_COARSE, &t);
     tms = (t.tv_sec)*1000 + (t.tv_nsec)/(1000*1000);
 
 	return tms;
diff --git a/test/trace_delay.c b/test/trace_delay.c
index 08c449f..5ec7e4e 100644
--- a/test/trace_delay.c
+++ b/test/trace_delay.c
@@ -242,7 +242,7 @@ static uint64_t get_cur_time_in_ns(void)
 	struct timespec cur_time;

 	uint64_t cur_second, cur_nano;

 

-	clock_gettime(CLOCK_REALTIME, &cur_time);

+	clock_gettime(CLOCK_MONOTONIC, &cur_time);

 

 	cur_second = cur_time.tv_sec;

 	cur_nano = cur_time.tv_nsec;