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 750c74b..69e52c7 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" @@ -56,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); } } @@ -83,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); } @@ -135,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; } @@ -250,6 +264,7 @@ bool HandleMessage(PerfMessage* pMsg) return retVal; } + void RunLoop(PerfMsgQueue* pQueue) { bool bContinue = true; @@ -261,7 +276,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 +301,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(); 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); diff --git a/src/rdk_perf_msgqueue.cpp b/src/rdk_perf_msgqueue.cpp index 71f1691..3dae3b3 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,15 @@ 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) +#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; @@ -51,8 +61,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) { @@ -89,9 +98,25 @@ 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); +#if defined(MEASURE_MQ_SEND_USAGE) && defined(PERF_SHOW_CPU) + 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 } +#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; @@ -102,24 +127,46 @@ 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(); +#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))); + 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) { + m_stats_msgExit++; + } 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; - memcpy((void*)msg.msg_data.entry.szName, (void*)szName, MIN((size_t)(MAX_NAME_LEN - 1), strlen(szName))); +#endif + 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(); @@ -156,10 +203,27 @@ 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; + if(m_stats_msgSent < ULONG_MAX) { + m_stats_msgSent++; + } } else { LOG(eError, "Unable to send message of type %d\n", pMsg->type); @@ -224,29 +288,42 @@ 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; } uint32_t PerfMsgQueue::AddRef() { SCOPED_LOCK(); - m_RefCount++; + if(m_RefCount < UINT_MAX) { + m_RefCount++; + } return m_RefCount; } 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; } @@ -280,4 +357,27 @@ bool PerfMsgQueue::IsQueueCreated(const char* szQueueName) } return retVal; -} \ No newline at end of file +} + +int PerfMsgQueue::getSystemMaxMsg(void) +{ + static const 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..8bfde93 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 @@ -131,24 +142,47 @@ 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(); +#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); 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; 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; +#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 }; 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