From 3b7e1a1c1d259891a4e3c6287f2ea0c10ba67a65 Mon Sep 17 00:00:00 2001 From: Mario Luzeiro Date: Mon, 31 Jul 2023 18:36:40 +0100 Subject: [PATCH 01/13] Register Ctrl+C signal handler --- service/perfservice.cpp | 31 +++++++++++++++++++++++++------ 1 file changed, 25 insertions(+), 6 deletions(-) diff --git a/service/perfservice.cpp b/service/perfservice.cpp index 750c74b..a60b3e3 100644 --- a/service/perfservice.cpp +++ b/service/perfservice.cpp @@ -25,6 +25,7 @@ #include #include #include +#include #include "rdk_perf_logging.h" #include "rdk_perf_msgqueue.h" @@ -250,6 +251,7 @@ bool HandleMessage(PerfMessage* pMsg) return retVal; } + void RunLoop(PerfMsgQueue* pQueue) { bool bContinue = true; @@ -261,7 +263,7 @@ void RunLoop(PerfMsgQueue* pQueue) pQueue->ReceiveMessage(&msg, MESSAGE_TIMEOUT); //TEST if(msg.type == eExitQueue || msg.type == eMaxType) { - // Exit loop + LOG(eWarning, "Exit loop\n"); bContinue = false; } else if(msg.type == eNoMessage) { @@ -286,26 +288,43 @@ void RunLoop(PerfMsgQueue* pQueue) LOG(eWarning, "RunLoop exiting\n"); return; } + +static PerfMsgQueue* s_pQueue = NULL; + +static void ctrlc_handler_callback(int, siginfo_t* ,void* contex) +{ + LOG(eWarning, "Ctrl+C pressed\n"); + if(s_pQueue != NULL) { + s_pQueue->SendMessage(eExitQueue, NULL, 0, 0); + } +} + int main(int argc, char *argv[]) { LOG(eWarning, "Enter perfservice app %s\n", __DATE__); + // Register Ctrl+C handler + struct sigaction sa; + sa.sa_sigaction = ctrlc_handler_callback; + sa.sa_flags = SA_SIGINFO; + sigaction(SIGINT, &sa, NULL); + RDKPerf_InitializeMap(); // // Does the queue exist if(PerfMsgQueue::IsQueueCreated(RDK_PERF_MSG_QUEUE_NAME)) { - // Queue exists, service is a duplicate + LOG(eError, "Queue exists, service is a duplicate\n"); exit(-1); } // Create Queue - PerfMsgQueue* pQueue = PerfMsgQueue::GetQueue(RDK_PERF_MSG_QUEUE_NAME, true); - if(pQueue != NULL) { + s_pQueue = PerfMsgQueue::GetQueue(RDK_PERF_MSG_QUEUE_NAME, true); + if(s_pQueue != NULL) { // Have Queue, start retrieven messages - RunLoop(pQueue); + RunLoop(s_pQueue); // RunLoop exited, cleanup - pQueue->Release(); + s_pQueue->Release(); } RDKPerf_DeleteMap(); From 576a790c1e8ba10438ca368341a9a4d88a856091 Mon Sep 17 00:00:00 2001 From: Mario Luzeiro Date: Wed, 2 Aug 2023 16:24:42 +0100 Subject: [PATCH 02/13] Implement getSystemMaxMsg Gets the value of "sysctl fs.mqueue.msg_max" --- src/rdk_perf_msgqueue.cpp | 28 +++++++++++++++++++++++++--- src/rdk_perf_msgqueue.h | 2 ++ 2 files changed, 27 insertions(+), 3 deletions(-) diff --git a/src/rdk_perf_msgqueue.cpp b/src/rdk_perf_msgqueue.cpp index 71f1691..7e3344f 100644 --- a/src/rdk_perf_msgqueue.cpp +++ b/src/rdk_perf_msgqueue.cpp @@ -51,8 +51,7 @@ PerfMsgQueue::PerfMsgQueue(const char* szQueueName, bool bService) flags = O_WRONLY; } - // m_queue = mq_open(szQueueName, flags); - new_attr.mq_maxmsg = 10; + new_attr.mq_maxmsg = getSystemMaxMsg(); new_attr.mq_msgsize = sizeof(PerfMessage); if(bService) { @@ -280,4 +279,27 @@ bool PerfMsgQueue::IsQueueCreated(const char* szQueueName) } return retVal; -} \ No newline at end of file +} + +int PerfMsgQueue::getSystemMaxMsg(void) +{ + static char* msgmax_filename = "/proc/sys/fs/mqueue/msg_max"; + + FILE* fp = fopen(msgmax_filename, "r"); + + if(fp == NULL) { + LOG(eError, "Can't open \"%s\"\n", msgmax_filename); + return 0; + } + + int msg_max = 0; + char buffer[12]; + + if(fgets(buffer, 12, fp) != NULL) { + msg_max = atoi(buffer); + }else{ + LOG(eError, "Can't parse content of \"%s\"\n", msgmax_filename); + } + + return msg_max; +} diff --git a/src/rdk_perf_msgqueue.h b/src/rdk_perf_msgqueue.h index 2e314a9..cc7a077 100644 --- a/src/rdk_perf_msgqueue.h +++ b/src/rdk_perf_msgqueue.h @@ -143,6 +143,8 @@ class PerfMsgQueue static PerfMsgQueue* GetQueue(const char* szQueueName, bool bService); static bool IsQueueCreated(const char* szQueueName); +private: + static int getSystemMaxMsg(void); private: mqd_t m_queue; struct mq_attr m_queue_attr; From efefa07fe98c08432444e2ad091eb6c4927c17ee Mon Sep 17 00:00:00 2001 From: Mario Luzeiro Date: Wed, 2 Aug 2023 16:27:55 +0100 Subject: [PATCH 03/13] make variable const --- src/rdk_perf_msgqueue.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/rdk_perf_msgqueue.cpp b/src/rdk_perf_msgqueue.cpp index 7e3344f..22a47e8 100644 --- a/src/rdk_perf_msgqueue.cpp +++ b/src/rdk_perf_msgqueue.cpp @@ -283,7 +283,7 @@ bool PerfMsgQueue::IsQueueCreated(const char* szQueueName) int PerfMsgQueue::getSystemMaxMsg(void) { - static char* msgmax_filename = "/proc/sys/fs/mqueue/msg_max"; + static const char* msgmax_filename = "/proc/sys/fs/mqueue/msg_max"; FILE* fp = fopen(msgmax_filename, "r"); From b71885b7955af2f6924c6848aac8ba2b40b0b65b Mon Sep 17 00:00:00 2001 From: Mario Luzeiro Date: Wed, 2 Aug 2023 16:52:59 +0100 Subject: [PATCH 04/13] make constructor private (singleton pattern) move AddRef to private --- src/rdk_perf_msgqueue.h | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/src/rdk_perf_msgqueue.h b/src/rdk_perf_msgqueue.h index cc7a077..dfd51d6 100644 --- a/src/rdk_perf_msgqueue.h +++ b/src/rdk_perf_msgqueue.h @@ -131,10 +131,11 @@ typedef struct _PerfMessage class PerfMsgQueue { public: - PerfMsgQueue(const char* szQueueName, bool bService); + PerfMsgQueue(PerfMsgQueue const &) = delete; + void operator=(PerfMsgQueue const &) = delete; + ~PerfMsgQueue(); - uint32_t AddRef(); uint32_t Release(); bool SendMessage(MessageType type, const char* szName = NULL, uint64_t nTimeStamp = 0, int32_t nThresholdInUS = -1); @@ -143,8 +144,14 @@ class PerfMsgQueue static PerfMsgQueue* GetQueue(const char* szQueueName, bool bService); static bool IsQueueCreated(const char* szQueueName); + private: + PerfMsgQueue(const char* szQueueName, bool bService); + + uint32_t AddRef(); + static int getSystemMaxMsg(void); + private: mqd_t m_queue; struct mq_attr m_queue_attr; From 4ff852fbd0aeda8bd2566c1db3c14d8afbe7c61e Mon Sep 17 00:00:00 2001 From: Mario Luzeiro Date: Thu, 3 Aug 2023 13:07:54 +0100 Subject: [PATCH 05/13] Check if refcount is >0 before decrease it --- src/rdk_perf_msgqueue.cpp | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/src/rdk_perf_msgqueue.cpp b/src/rdk_perf_msgqueue.cpp index 22a47e8..943784c 100644 --- a/src/rdk_perf_msgqueue.cpp +++ b/src/rdk_perf_msgqueue.cpp @@ -241,11 +241,21 @@ uint32_t PerfMsgQueue::AddRef() uint32_t PerfMsgQueue::Release() { SCOPED_LOCK(); - uint32_t retVal = --m_RefCount; + + if(m_RefCount > 0) { + m_RefCount--; + } + else { + LOG(eError, "RefCount was 0 already - not expected\n"); + } + + uint32_t retVal = m_RefCount; + if(m_RefCount == 0) { LOG(eWarning, "RefCount at 0, deleting Queue\n"); delete this; } + return retVal; } From 9766678229e71df95d07a0d87cbd8913717951dd Mon Sep 17 00:00:00 2001 From: Mario Luzeiro Date: Thu, 3 Aug 2023 13:11:16 +0100 Subject: [PATCH 06/13] protect for overflow --- src/rdk_perf_msgqueue.cpp | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/rdk_perf_msgqueue.cpp b/src/rdk_perf_msgqueue.cpp index 943784c..1ddd2a7 100644 --- a/src/rdk_perf_msgqueue.cpp +++ b/src/rdk_perf_msgqueue.cpp @@ -234,7 +234,9 @@ bool PerfMsgQueue::ReceiveMessage(PerfMessage* pMsg, int32_t nTimeoutInMS) uint32_t PerfMsgQueue::AddRef() { SCOPED_LOCK(); - m_RefCount++; + if(m_RefCount < UINT_MAX) { + m_RefCount++; + } return m_RefCount; } From 632fe4c68067543a2ea7564c30765eccccff6b15 Mon Sep 17 00:00:00 2001 From: Mario Luzeiro Date: Thu, 3 Aug 2023 13:12:21 +0100 Subject: [PATCH 07/13] add statistics to msgqueue do not check for curmsg depth --- src/rdk_perf_msgqueue.cpp | 29 +++++++++++++++++++++++++---- src/rdk_perf_msgqueue.h | 5 +++++ 2 files changed, 30 insertions(+), 4 deletions(-) diff --git a/src/rdk_perf_msgqueue.cpp b/src/rdk_perf_msgqueue.cpp index 1ddd2a7..8fe6539 100644 --- a/src/rdk_perf_msgqueue.cpp +++ b/src/rdk_perf_msgqueue.cpp @@ -30,6 +30,7 @@ #include /* For O_* constants */ #include /* For mode constants */ #include +#include #include static PerfMsgQueue* s_PerfQueue = NULL; @@ -37,6 +38,10 @@ static PerfMsgQueue* s_PerfQueue = NULL; PerfMsgQueue::PerfMsgQueue(const char* szQueueName, bool bService) : m_bService(bService) , m_RefCount(0) +, m_stats_msgReceived(0) +, m_stats_msgSent(0) +, m_stats_msgEntry(0) +, m_stats_msgExit(0) { int flags = 0; mode_t mode = S_IRWXU | S_IRWXG | S_IRWXO; @@ -88,6 +93,12 @@ PerfMsgQueue::~PerfMsgQueue() if(m_bService) { mq_unlink(m_szName); } + + LOG(eWarning, "Messages Statistics\n"); + LOG(eWarning, "\tReceived: %lu\n", m_stats_msgReceived); + LOG(eWarning, "\tSent: %lu\n", m_stats_msgSent); + LOG(eWarning, "\tEntry: %lu\n", m_stats_msgEntry); + LOG(eWarning, "\tExit: %lu\n", m_stats_msgExit); } bool PerfMsgQueue::SendMessage(MessageType type, const char* szName, uint64_t nTimeStamp, int32_t nThresholdInUS) @@ -101,6 +112,9 @@ bool PerfMsgQueue::SendMessage(MessageType type, const char* szName, uint64_t nT msg.type = type; switch(type) { case eEntry: + if(m_stats_msgEntry < ULONG_MAX) { + m_stats_msgEntry++; + } msg.msg_data.entry.pID = getpid(); msg.msg_data.entry.tID = pthread_self(); msg.msg_data.entry.nTimeStamp = nTimeStamp; @@ -115,6 +129,9 @@ bool PerfMsgQueue::SendMessage(MessageType type, const char* szName, uint64_t nT memcpy((void*)msg.msg_data.entry.szName, (void*)szName, MIN((size_t)(MAX_NAME_LEN - 1), strlen(szName))); break; case eExit: + if(m_stats_msgExit < ULONG_MAX) { + m_stats_msgExit++; + } msg.msg_data.exit.pID = getpid(); msg.msg_data.exit.tID = pthread_self(); msg.msg_data.exit.nTimeStamp = nTimeStamp; @@ -159,6 +176,9 @@ bool PerfMsgQueue::SendMessage(PerfMessage* pMsg) if(result == 0) { // Success retVal = true; + if(m_stats_msgSent < ULONG_MAX) { + m_stats_msgSent++; + } } else { LOG(eError, "Unable to send message of type %d\n", pMsg->type); @@ -223,11 +243,12 @@ bool PerfMsgQueue::ReceiveMessage(PerfMessage* pMsg, int32_t nTimeoutInMS) } } - if (mq_getattr(m_queue, &m_queue_attr) != -1) { - if(m_queue_attr.mq_curmsgs > m_queue_attr.mq_maxmsg - 2) { - LOG(eWarning, "Queue Depth at threshold %d max %d\n", m_queue_attr.mq_curmsgs, m_queue_attr.mq_maxmsg); + if(retVal) { + if(m_stats_msgReceived < ULONG_MAX) { + m_stats_msgReceived++; } - } + } + return retVal; } diff --git a/src/rdk_perf_msgqueue.h b/src/rdk_perf_msgqueue.h index dfd51d6..41010cf 100644 --- a/src/rdk_perf_msgqueue.h +++ b/src/rdk_perf_msgqueue.h @@ -158,6 +158,11 @@ class PerfMsgQueue bool m_bService; char m_szName[MAX_NAME_LEN]; uint32_t m_RefCount; + // Statistics + uint64_t m_stats_msgReceived; + uint64_t m_stats_msgSent; + uint64_t m_stats_msgEntry; + uint64_t m_stats_msgExit; }; From 5e965c67a2a43a3b9bb37a98054b1ce598fb1c80 Mon Sep 17 00:00:00 2001 From: Mario Luzeiro Date: Fri, 4 Aug 2023 14:51:59 +0100 Subject: [PATCH 08/13] add log, fix log text and format --- service/perfservice.cpp | 3 ++- src/rdk_perf_record.cpp | 2 +- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/service/perfservice.cpp b/service/perfservice.cpp index a60b3e3..e064883 100644 --- a/service/perfservice.cpp +++ b/service/perfservice.cpp @@ -57,9 +57,10 @@ PerfTree* GetTree(pid_t pID, pthread_t tID, char* szName, bool bCreate = false) if(pTree == NULL) { if(bCreate) { pTree = pProcess->NewTree(tID); + LOG(eError, "Tree created %X\n", tID); } else { - LOG(eError, "Tree not found %x but create not enabled\n", tID); + LOG(eError, "Tree not found %X but create not enabled\n", tID); } } diff --git a/src/rdk_perf_record.cpp b/src/rdk_perf_record.cpp index a1775fb..43d4754 100644 --- a/src/rdk_perf_record.cpp +++ b/src/rdk_perf_record.cpp @@ -52,7 +52,7 @@ PerfRecord::PerfRecord(std::string elementName) // no existing PID in map pProcess = new PerfProcess(pID); RDKPerf_InsertProcess(pID, pProcess); - LOG(eWarning, "Creating new process element %X for elemant %s\n", pProcess, m_elementName.c_str()); + LOG(eWarning, "Creating new process element %X for element %s\n", pProcess, m_elementName.c_str()); } #ifdef USE_TIMESTAMP From 5a23b47a18299b5b51c944f9898f5c1daf1d84f1 Mon Sep 17 00:00:00 2001 From: Mario Luzeiro Date: Fri, 4 Aug 2023 16:46:22 +0100 Subject: [PATCH 09/13] take out TimeStamp --- src/rdk_perf_clock.cpp | 5 +++++ src/rdk_perf_clock.h | 15 ++++++++------- 2 files changed, 13 insertions(+), 7 deletions(-) diff --git a/src/rdk_perf_clock.cpp b/src/rdk_perf_clock.cpp index fd8008a..f02a630 100644 --- a/src/rdk_perf_clock.cpp +++ b/src/rdk_perf_clock.cpp @@ -159,3 +159,8 @@ PerfClock* PerfClock::Now() return retVal; } + +const TimeStamp& PerfClock::GetTimeStamp() const +{ + return m_timeStamp; +} \ No newline at end of file diff --git a/src/rdk_perf_clock.h b/src/rdk_perf_clock.h index ada788e..474fdc4 100644 --- a/src/rdk_perf_clock.h +++ b/src/rdk_perf_clock.h @@ -25,6 +25,12 @@ #include #include // time_t +typedef struct _TimeStamp +{ + uint64_t wallClock; + uint64_t userCPU; + uint64_t systemCPU; +} TimeStamp; class PerfClock { @@ -38,13 +44,6 @@ class PerfClock microsecond = 1, millisecond = 1000, } TimeUnit; - - typedef struct _TimeStamp - { - uint64_t wallClock; - uint64_t userCPU; - uint64_t systemCPU; - } TimeStamp; PerfClock(TimeStamp* pTS); PerfClock(); @@ -64,6 +63,8 @@ class PerfClock static PerfClock* Now(); static void Now(PerfClock* pClock, Operation operation = Marker); + const TimeStamp& GetTimeStamp() const; + private: uint64_t ConvertToUS(time_t sec, time_t usec); From ba9297ea73c70603cbb77e22a11060ead635ec1e Mon Sep 17 00:00:00 2001 From: Mario Luzeiro Date: Thu, 10 Aug 2023 09:24:17 +0100 Subject: [PATCH 10/13] add clockTimeStamp for PERF_SHOW_CPU --- rdkperf/rdk_perf.cpp | 30 ++++++++++++++++++++++++------ rdkperf/rdk_perf.h | 8 +++++++- service/perfservice.cpp | 14 +++++++++++++- src/rdk_perf_msgqueue.cpp | 17 +++++++++++++++++ src/rdk_perf_msgqueue.h | 15 +++++++++++++++ 5 files changed, 76 insertions(+), 8 deletions(-) diff --git a/rdkperf/rdk_perf.cpp b/rdkperf/rdk_perf.cpp index 37bb00e..1a0ff6e 100644 --- a/rdkperf/rdk_perf.cpp +++ b/rdkperf/rdk_perf.cpp @@ -36,6 +36,9 @@ #include "rdk_perf_process.h" #include "rdk_perf_tree.h" // Needs to come after rdk_perf_process because of forward declaration of PerfTree #include "rdk_perf.h" +#ifdef PERF_SHOW_CPU +#include "rdk_perf_clock.h" +#endif #include @@ -296,15 +299,20 @@ RDKPerfInProc::~RDKPerfInProc() RDKPerfRemote::RDKPerfRemote(const char* szName) : m_szName(szName) , m_nThresholdInUS(0) -, m_EndTime(0) { +#ifndef PERF_SHOW_CPU m_StartTime = PerfRecord::TimeStamp(); - +#endif // Send enter event #ifdef PERF_REMOTE if(s_pQueue == NULL) s_pQueue = PerfMsgQueue::GetQueue(RDK_PERF_MSG_QUEUE_NAME, false); if(s_pQueue != NULL) { +#ifdef PERF_SHOW_CPU + PerfClock::Now(&m_clock, PerfClock::Marker); + s_pQueue->SendMessage(eEntry, m_szName, NULL, m_nThresholdInUS); +#else s_pQueue->SendMessage(eEntry, m_szName, m_StartTime, m_nThresholdInUS); +#endif } else { LOG(eError, "Could not get Message Queue to send perf events\n"); @@ -316,13 +324,19 @@ RDKPerfRemote::RDKPerfRemote(const char* szName, uint32_t nThresholdInUS) : m_szName(szName) , m_nThresholdInUS(nThresholdInUS) { +#ifndef PERF_SHOW_CPU m_StartTime = PerfRecord::TimeStamp(); - +#endif // Send enter event #ifdef PERF_REMOTE if(s_pQueue == NULL) s_pQueue = PerfMsgQueue::GetQueue(RDK_PERF_MSG_QUEUE_NAME, false); if(s_pQueue != NULL) { +#ifdef PERF_SHOW_CPU + PerfClock::Now(&m_clock, PerfClock::Marker); + s_pQueue->SendMessage(eEntry, m_szName, NULL, nThresholdInUS); +#else s_pQueue->SendMessage(eEntry, m_szName, m_StartTime, nThresholdInUS); +#endif } else { LOG(eError, "Could not get Message Queue to send perf events\n"); @@ -344,12 +358,16 @@ void RDKPerfRemote::SetThreshhold(uint32_t nThresholdInUS) RDKPerfRemote::~RDKPerfRemote() { - m_EndTime = PerfRecord::TimeStamp(); - // Send close event #ifdef PERF_REMOTE if(s_pQueue != NULL) { - s_pQueue->SendMessage(eExit, m_szName, m_EndTime - m_StartTime); +#ifdef PERF_SHOW_CPU + PerfClock::Now(&m_clock, PerfClock::Elapsed); + s_pQueue->SendMessage(eExit, m_szName, &m_clock.GetTimeStamp(), m_nThresholdInUS); +#else + const uint64_t endTime = PerfRecord::TimeStamp(); + s_pQueue->SendMessage(eExit, m_szName, endTime - m_StartTime); +#endif } else { LOG(eError, "Could not get Message Queue to send perf events\n"); diff --git a/rdkperf/rdk_perf.h b/rdkperf/rdk_perf.h index ae2daac..cd0c029 100644 --- a/rdkperf/rdk_perf.h +++ b/rdkperf/rdk_perf.h @@ -34,6 +34,9 @@ #include "rdk_perf_record.h" //#include "rdk_perf_node.h" +#ifdef PERF_SHOW_CPU +#include "rdk_perf_clock.h" +#endif #define FUNC_METRICS_START(depth) \ { \ @@ -95,8 +98,11 @@ class RDKPerfRemote private: const char* m_szName; uint32_t m_nThresholdInUS; +#ifdef PERF_SHOW_CPU + PerfClock m_clock; +#else uint64_t m_StartTime; - uint64_t m_EndTime; +#endif }; diff --git a/service/perfservice.cpp b/service/perfservice.cpp index e064883..69e52c7 100644 --- a/service/perfservice.cpp +++ b/service/perfservice.cpp @@ -85,7 +85,12 @@ bool HandleEntry(PerfMessage* pMsg) PerfNode* pNode = pTree->AddNode(szName, tID, szThreadName, - pMsg->msg_data.entry.nTimeStamp); +#ifdef PERF_SHOW_CPU + 0 +#else + pMsg->msg_data.entry.nTimeStamp +#endif + ); if(pMsg->msg_data.entry.nThresholdInUS > 0) { pNode->SetThreshold(pMsg->msg_data.entry.nThresholdInUS); } @@ -137,7 +142,14 @@ bool HandleExit(PerfMessage* pMsg) PerfNode* pNode = pTree->GetStack()->top(); if(pNode != NULL && pNode->GetName().compare(szName) == 0) { +#ifdef PERF_SHOW_CPU + PerfClock deltaClock(&pMsg->msg_data.exit.clkTimeStamp); + pNode->IncrementData(deltaClock.GetWallClock(), + deltaClock.GetUserCPU(), + deltaClock.GetSystemCPU()); +#else pNode->IncrementData(pMsg->msg_data.exit.nTimeStamp, 0, 0); +#endif pNode->CloseNode(); retVal = true; } diff --git a/src/rdk_perf_msgqueue.cpp b/src/rdk_perf_msgqueue.cpp index 8fe6539..518d548 100644 --- a/src/rdk_perf_msgqueue.cpp +++ b/src/rdk_perf_msgqueue.cpp @@ -101,7 +101,11 @@ PerfMsgQueue::~PerfMsgQueue() LOG(eWarning, "\tExit: %lu\n", m_stats_msgExit); } +#ifdef PERF_SHOW_CPU +bool PerfMsgQueue::SendMessage(MessageType type, const char* szName, const TimeStamp* clockTimeStamp, int32_t nThresholdInUS) +#else bool PerfMsgQueue::SendMessage(MessageType type, const char* szName, uint64_t nTimeStamp, int32_t nThresholdInUS) +#endif { bool retVal = true; PerfMessage msg; @@ -117,7 +121,11 @@ bool PerfMsgQueue::SendMessage(MessageType type, const char* szName, uint64_t nT } msg.msg_data.entry.pID = getpid(); msg.msg_data.entry.tID = pthread_self(); +#ifdef PERF_SHOW_CPU + // No need +#else msg.msg_data.entry.nTimeStamp = nTimeStamp; +#endif msg.msg_data.entry.nThresholdInUS = nThresholdInUS; pthread_getname_np(msg.msg_data.entry.tID, msg.msg_data.entry.szThreadName, MAX_NAME_LEN); memcpy((void*)msg.msg_data.entry.szName, (void*)szName, MIN((size_t)(MAX_NAME_LEN - 1), strlen(szName))); @@ -134,7 +142,16 @@ bool PerfMsgQueue::SendMessage(MessageType type, const char* szName, uint64_t nT } msg.msg_data.exit.pID = getpid(); msg.msg_data.exit.tID = pthread_self(); +#ifdef PERF_SHOW_CPU + if(clockTimeStamp != nullptr) { + msg.msg_data.exit.clkTimeStamp = *clockTimeStamp; + } + else { + LOG(eError, "clockTimeStamp is null"); + } +#else msg.msg_data.exit.nTimeStamp = nTimeStamp; +#endif memcpy((void*)msg.msg_data.entry.szName, (void*)szName, MIN((size_t)(MAX_NAME_LEN - 1), strlen(szName))); break; case eReportThread: diff --git a/src/rdk_perf_msgqueue.h b/src/rdk_perf_msgqueue.h index 41010cf..068d621 100644 --- a/src/rdk_perf_msgqueue.h +++ b/src/rdk_perf_msgqueue.h @@ -29,6 +29,9 @@ #include "rdk_perf_logging.h" #include "rdk_perf_scopedlock.h" +#ifdef PERF_SHOW_CPU +#include "rdk_perf_clock.h" +#endif #include #include /* For O_* constants */ @@ -67,7 +70,11 @@ typedef struct _EntryMessage pthread_t tID; char szName[MAX_NAME_LEN]; char szThreadName[MAX_NAME_LEN]; +#ifdef PERF_SHOW_CPU + // No need +#else uint64_t nTimeStamp; +#endif int32_t nThresholdInUS; } EntryMessage; @@ -76,7 +83,11 @@ typedef struct _ExitMessage pid_t pID; pthread_t tID; char szName[MAX_NAME_LEN]; +#ifdef PERF_SHOW_CPU + TimeStamp clkTimeStamp; +#else uint64_t nTimeStamp; +#endif } ExitMessage; typedef struct _ThresholdMessage @@ -138,7 +149,11 @@ class PerfMsgQueue uint32_t Release(); +#ifdef PERF_SHOW_CPU + bool SendMessage(MessageType type, const char* szName = NULL, const TimeStamp* clockTimeStamp = nullptr, int32_t nThresholdInUS = -1); +#else bool SendMessage(MessageType type, const char* szName = NULL, uint64_t nTimeStamp = 0, int32_t nThresholdInUS = -1); +#endif bool SendMessage(PerfMessage* pMsg); bool ReceiveMessage(PerfMessage* pMsg, int32_t nTimeoutInMS = 0); From 384c058c7da6e6c7f070d5a5f4d0ba786f8f5d7d Mon Sep 17 00:00:00 2001 From: Mario Luzeiro Date: Fri, 11 Aug 2023 16:55:38 +0100 Subject: [PATCH 11/13] optimize by not using strlen and fix exit.szName --- src/rdk_perf_msgqueue.cpp | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/src/rdk_perf_msgqueue.cpp b/src/rdk_perf_msgqueue.cpp index 518d548..1c25bc3 100644 --- a/src/rdk_perf_msgqueue.cpp +++ b/src/rdk_perf_msgqueue.cpp @@ -128,13 +128,15 @@ bool PerfMsgQueue::SendMessage(MessageType type, const char* szName, uint64_t nT #endif msg.msg_data.entry.nThresholdInUS = nThresholdInUS; pthread_getname_np(msg.msg_data.entry.tID, msg.msg_data.entry.szThreadName, MAX_NAME_LEN); - memcpy((void*)msg.msg_data.entry.szName, (void*)szName, MIN((size_t)(MAX_NAME_LEN - 1), strlen(szName))); + strncpy(msg.msg_data.entry.szName, szName, MAX_NAME_LEN); + msg.msg_data.entry.szName[MAX_NAME_LEN - 1] = 0; break; case eThreshold: msg.msg_data.entry.pID = getpid(); msg.msg_data.entry.tID = pthread_self(); msg.msg_data.entry.nThresholdInUS = nThresholdInUS; - memcpy((void*)msg.msg_data.entry.szName, (void*)szName, MIN((size_t)(MAX_NAME_LEN - 1), strlen(szName))); + strncpy(msg.msg_data.entry.szName, szName, MAX_NAME_LEN); + msg.msg_data.entry.szName[MAX_NAME_LEN - 1] = 0; break; case eExit: if(m_stats_msgExit < ULONG_MAX) { @@ -152,7 +154,8 @@ bool PerfMsgQueue::SendMessage(MessageType type, const char* szName, uint64_t nT #else msg.msg_data.exit.nTimeStamp = nTimeStamp; #endif - memcpy((void*)msg.msg_data.entry.szName, (void*)szName, MIN((size_t)(MAX_NAME_LEN - 1), strlen(szName))); + strncpy(msg.msg_data.exit.szName, szName, MAX_NAME_LEN); + msg.msg_data.exit.szName[MAX_NAME_LEN - 1] = 0; break; case eReportThread: msg.msg_data.report_thread.pID = getpid(); From 2202edeb0e289ec31a25b3316b53258c27b8c8a7 Mon Sep 17 00:00:00 2001 From: Mario Luzeiro Date: Wed, 16 Aug 2023 18:38:12 +0100 Subject: [PATCH 12/13] measure mq_send cpu usage if MEASURE_MQ_SEND_USAGE and PERF_SHOW_CPU are defined --- src/rdk_perf_msgqueue.cpp | 25 +++++++++++++++++++++++++ src/rdk_perf_msgqueue.h | 5 +++++ 2 files changed, 30 insertions(+) diff --git a/src/rdk_perf_msgqueue.cpp b/src/rdk_perf_msgqueue.cpp index 1c25bc3..392ac12 100644 --- a/src/rdk_perf_msgqueue.cpp +++ b/src/rdk_perf_msgqueue.cpp @@ -42,6 +42,11 @@ PerfMsgQueue::PerfMsgQueue(const char* szQueueName, bool bService) , m_stats_msgSent(0) , m_stats_msgEntry(0) , m_stats_msgExit(0) +#if defined(MEASURE_MQ_SEND_USAGE) && defined(PERF_SHOW_CPU) +, m_cpu_wall_us(0) +, m_cpu_user_us(0) +, m_cpu_system_us(0) +#endif { int flags = 0; mode_t mode = S_IRWXU | S_IRWXG | S_IRWXO; @@ -99,6 +104,12 @@ PerfMsgQueue::~PerfMsgQueue() LOG(eWarning, "\tSent: %lu\n", m_stats_msgSent); LOG(eWarning, "\tEntry: %lu\n", m_stats_msgEntry); LOG(eWarning, "\tExit: %lu\n", m_stats_msgExit); +#if defined(MEASURE_MQ_SEND_USAGE) && defined(PERF_SHOW_CPU) + LOG(eWarning, "MQ_SEND CPU usage (microseconds):\n"); + LOG(eWarning, "\tWall: %lu\n", m_cpu_wall_us); + LOG(eWarning, "\tUser: %lu\n", m_cpu_user_us); + LOG(eWarning, "\tSystem: %lu\n", m_cpu_system_us); +#endif } #ifdef PERF_SHOW_CPU @@ -192,7 +203,21 @@ bool PerfMsgQueue::SendMessage(PerfMessage* pMsg) bool retVal = false; unsigned int nPriority = 5; +#if defined(MEASURE_MQ_SEND_USAGE) && defined(PERF_SHOW_CPU) + PerfClock timer; + PerfClock::Now(&timer, PerfClock::Marker); +#endif + int result = mq_send(m_queue, (const char*)pMsg, sizeof(PerfMessage), nPriority); + +#if defined(MEASURE_MQ_SEND_USAGE) && defined(PERF_SHOW_CPU) + PerfClock::Now(&timer, PerfClock::Elapsed); + + m_cpu_wall_us += timer.GetWallClock(); + m_cpu_user_us += timer.GetUserCPU(); + m_cpu_system_us += timer.GetSystemCPU(); +#endif + if(result == 0) { // Success retVal = true; diff --git a/src/rdk_perf_msgqueue.h b/src/rdk_perf_msgqueue.h index 068d621..8bfde93 100644 --- a/src/rdk_perf_msgqueue.h +++ b/src/rdk_perf_msgqueue.h @@ -178,6 +178,11 @@ class PerfMsgQueue uint64_t m_stats_msgSent; uint64_t m_stats_msgEntry; uint64_t m_stats_msgExit; +#if defined(MEASURE_MQ_SEND_USAGE) && defined(PERF_SHOW_CPU) + uint64_t m_cpu_wall_us; + uint64_t m_cpu_user_us; + uint64_t m_cpu_system_us; +#endif }; From c87d720065416ae4895b81376c48f5c7660d4f1d Mon Sep 17 00:00:00 2001 From: Mario Luzeiro Date: Thu, 17 Aug 2023 14:38:20 +0100 Subject: [PATCH 13/13] show based on percentage --- src/rdk_perf_msgqueue.cpp | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/rdk_perf_msgqueue.cpp b/src/rdk_perf_msgqueue.cpp index 392ac12..3dae3b3 100644 --- a/src/rdk_perf_msgqueue.cpp +++ b/src/rdk_perf_msgqueue.cpp @@ -105,10 +105,10 @@ PerfMsgQueue::~PerfMsgQueue() LOG(eWarning, "\tEntry: %lu\n", m_stats_msgEntry); LOG(eWarning, "\tExit: %lu\n", m_stats_msgExit); #if defined(MEASURE_MQ_SEND_USAGE) && defined(PERF_SHOW_CPU) - LOG(eWarning, "MQ_SEND CPU usage (microseconds):\n"); - LOG(eWarning, "\tWall: %lu\n", m_cpu_wall_us); - LOG(eWarning, "\tUser: %lu\n", m_cpu_user_us); - LOG(eWarning, "\tSystem: %lu\n", m_cpu_system_us); + LOG(eWarning, "mq_send CPU usage Total microseconds (microseconds/message):\n"); + LOG(eWarning, "\tWall: %lu (%lf)\n", m_cpu_wall_us, ((double)m_cpu_wall_us/(double)m_stats_msgSent)); + LOG(eWarning, "\tUser: %lu (%lf)\n", m_cpu_user_us, ((double)m_cpu_user_us/(double)m_stats_msgSent)); + LOG(eWarning, "\tSystem: %lu (%lf)\n", m_cpu_system_us, ((double)m_cpu_system_us/(double)m_stats_msgSent)); #endif }