!2 展示上次请求的时间信息，可估算占用主线程的长度

Framework/spbase/SpServerSessionFunction.cpp

@@ -11,6 +11,9 @@
 #include <winpr/wlog.h>
 #define TAG SPBASE_TAG("SpServerSessionFunction")
 
+std::chrono::steady_clock::time_point SpServerSessionFunction::m_last_Begintime(std::chrono::steady_clock::now());
+std::chrono::steady_clock::time_point SpServerSessionFunction::m_last_Endtime(std::chrono::steady_clock::now());
+
 SpServerSessionFunction::SpServerSessionFunction(SpEntity *pEntity, CServerSessionBase *pServerSessionBase, int remote_epid, int remote_svc_id, int conn_id)
 : m_uas(NULL), m_remote_ent(NULL), m_pServerSessionBase(pServerSessionBase)
 {
@@ -139,6 +142,12 @@ int SpServerSessionFunction::get_method_attr(int method_id, int method_sig, int
 
 void SpServerSessionFunction::on_req(int tsx_id, int method_id, int method_sig, int timeout, iobuffer_t **req_pkt)
 {
+	auto current = std::chrono::steady_clock::now();
+    auto duration = current - m_last_Endtime;
+	auto costDuration = m_last_Endtime - m_last_Begintime;
+	CSimpleString lastReqInfo = CSimpleString::Format("last req complete at %lldms ago, cost %lldms",
+	 std::chrono::duration_cast<std::chrono::milliseconds>(duration).count(),
+	  std::chrono::duration_cast<std::chrono::milliseconds>(costDuration).count());
 	if (NULL != *req_pkt)
 	{
         /** 目前这里的数据读取后面没有用途 [Gifur@2022624]*/
@@ -153,20 +162,31 @@ void SpServerSessionFunction::on_req(int tsx_id, int method_id, int method_sig,
 
 		iobuffer_get_linkInfo(*req_pkt, bussinessId, traceId, spanId, parentSpanId);
 
-		DbgWithLink(LOG_LEVEL_DEBUG, LOG_TYPE_SYSTEM).setAPI(__FUNCTION__)("on_req: tsx_id=%d, method_id=%d, method_sig=%d, pkt_size=%d, linkcontext=%s-%s-%s-%s", tsx_id, method_id, method_sig, iobuffer_get_length(*req_pkt), bussinessId, traceId, spanId, parentSpanId);
+		DbgWithLink(LOG_LEVEL_DEBUG, LOG_TYPE_SYSTEM).setAPI(__FUNCTION__)
+		("%s, on_req: tsx_id=%d, method_id=%d, method_sig=%d, pkt_size=%d, linkcontext=%s-%s-%s-%s",
+		 lastReqInfo.GetData(), tsx_id, method_id, method_sig, iobuffer_get_length(*req_pkt), bussinessId, traceId, spanId, parentSpanId);
 	}
 	else
-		DbgWithLink(LOG_LEVEL_DEBUG, LOG_TYPE_SYSTEM).setAPI(__FUNCTION__)("on_req: tsx_id=%d, method_id=%d, method_sig=%d, pkt_size=%d", tsx_id, method_id, method_sig, 0);
+		DbgWithLink(LOG_LEVEL_DEBUG, LOG_TYPE_SYSTEM).setAPI(__FUNCTION__)
+		("%s, on_req: tsx_id=%d, method_id=%d, method_sig=%d, pkt_size=%d", lastReqInfo.GetData(), tsx_id, method_id, method_sig, 0);
 	
 
 	CSmartPointer<ITransactionContext> spTmp;
 	SpTransactionContext *pTransactionContext = new SpTransactionContext(m_uas, 0, method_id, method_sig, timeout, req_pkt, tsx_id);
 	spTmp.Attach(pTransactionContext);
+	m_last_Begintime = std::chrono::steady_clock::now();
 	m_pServerSessionBase->OnRequest(spTmp);
+	m_last_Endtime = std::chrono::steady_clock::now();
 }
 
 void SpServerSessionFunction::on_info(int method_id, int method_sig, iobuffer_t **info_pkt)
 {
+	auto current = std::chrono::steady_clock::now();
+    auto duration = current - m_last_Endtime;
+	auto costDuration = m_last_Endtime - m_last_Begintime;
+	CSimpleString lastReqInfo = CSimpleString::Format("last req complete at %lldms ago, cost %lldms",
+	 std::chrono::duration_cast<std::chrono::milliseconds>(duration).count(),
+	  std::chrono::duration_cast<std::chrono::milliseconds>(costDuration).count());
 	if (NULL != *info_pkt)
 	{
 		char bussinessId[LINKINFO_BUSSID_LEN + 1];
@@ -178,19 +198,20 @@ void SpServerSessionFunction::on_info(int method_id, int method_sig, iobuffer_t
 		ZeroMemory(spanId, sizeof(spanId));
 		ZeroMemory(parentSpanId, sizeof(parentSpanId));
 		iobuffer_get_linkInfo(*info_pkt, bussinessId, traceId, spanId, parentSpanId);
-		DbgWithLink(LOG_LEVEL_DEBUG, LOG_TYPE_SYSTEM).setAPI(__FUNCTION__)("on_info: method_id=%d, method_sig=%d, pkt_size=%d, linkcontext=%s-%s-%s-%s", method_id, method_sig, iobuffer_get_length(*info_pkt), bussinessId, traceId, spanId, parentSpanId);
+		DbgWithLink(LOG_LEVEL_DEBUG, LOG_TYPE_SYSTEM).setAPI(__FUNCTION__)
+		("%s, on_info: method_id=%d, method_sig=%d, pkt_size=%d, linkcontext=%s-%s-%s-%s",
+		lastReqInfo.GetData(), method_id, method_sig, iobuffer_get_length(*info_pkt), bussinessId, traceId, spanId, parentSpanId);
 	}
 	else
-		DbgWithLink(LOG_LEVEL_DEBUG, LOG_TYPE_SYSTEM).setAPI(__FUNCTION__)("on_info: method_id=%d, method_sig=%d, pkt_size=%d", method_id, method_sig, 0);
-		
-
-
-	
+		DbgWithLink(LOG_LEVEL_DEBUG, LOG_TYPE_SYSTEM).setAPI(__FUNCTION__)
+		("%s, on_info: method_id=%d, method_sig=%d, pkt_size=%d",lastReqInfo.GetData(), method_id, method_sig, 0);
 
 	CSmartPointer<ITransactionContext> spTmp;
 	SpTransactionContext *pTransactionContext = new SpTransactionContext(m_uas, 1, method_id, method_sig, 0, info_pkt, -1);
 	spTmp.Attach(pTransactionContext);
+	m_last_Begintime = std::chrono::steady_clock::now();
 	m_pServerSessionBase->OnRequest(spTmp);
+	m_last_Endtime = std::chrono::steady_clock::now();
 }
 
 void SpServerSessionFunction::on_close(int error)

Framework/spbase/SpServerSessionFunction.h

@@ -4,6 +4,7 @@
 
 #include "sp_ses.h"
 #include "sp_mod.h"
+#include <chrono>
 
 class SpServerSessionFunction : public IServerSessionFunction
 {
@@ -32,4 +33,7 @@ private:
 	CServerSessionBase *m_pServerSessionBase;
 	sp_ses_uas_t *m_uas;
 	sp_entity_t *m_remote_ent;
+	static std::chrono::steady_clock::time_point m_last_Begintime;
+	static std::chrono::steady_clock::time_point m_last_Endtime;
+
 };