From 82bd7bde02c8bdb6ef856aadaf64add365125a6c Mon Sep 17 00:00:00 2001 From: leiguangyu Date: Wed, 1 Mar 2023 10:33:44 +0800 Subject: [PATCH] trace for usb Change-Id: Ie9ba87c16b8d7b60f3dc413c335e6831af5c7461 Signed-off-by: leiguangyu --- BUILD.gn | 4 ++++ src/common/define_plus.h | 13 +++++++++++++ src/common/file.cpp | 4 ++++ src/common/session.cpp | 13 +++++++++++++ src/common/transfer.cpp | 5 +++++ src/common/usb.cpp | 2 ++ src/daemon/daemon_usb.cpp | 7 +++++++ 7 files changed, 48 insertions(+) diff --git a/BUILD.gn b/BUILD.gn index 84bfec63..7dadbf83 100644 --- a/BUILD.gn +++ b/BUILD.gn @@ -137,6 +137,10 @@ template("hdcd_source_set") { if (image_name == "updater") { defines += [ "UPDATER_MODE" ] } + if (image_name == "system") { + defines += [ "HDC_TRACE" ] + external_deps += [ "hitrace_native:hitrace_meter" ] + } } if (hdc_version_check) { diff --git a/src/common/define_plus.h b/src/common/define_plus.h index 57603de5..6c531c66 100755 --- a/src/common/define_plus.h +++ b/src/common/define_plus.h @@ -17,6 +17,9 @@ #include #include +#ifdef HDC_TRACE +#include "hitrace_meter.h" +#endif namespace Hdc { // ############################# enum define ################################### @@ -32,6 +35,16 @@ enum LogLevel { }; #define WRITE_LOG(x, y...) Base::PrintLogEx(__FILE__, __LINE__, x, y) +#ifdef HDC_TRACE +#define StartTracePoint(value) StartTrace(HITRACE_TAG_HDCD, value) +#define FinishTracePoint() FinishTrace(HITRACE_TAG_HDCD) +#define StartTraceScope(value) HITRACE_METER_NAME(HITRACE_TAG_HDCD, value) +#else +#define StartTracePoint(value) +#define FinishTracePoint() +#define StartTraceScope(value) +#endif + enum MessageLevel { MSG_FAIL, MSG_INFO, diff --git a/src/common/file.cpp b/src/common/file.cpp index 54653fa2..89854f47 100644 --- a/src/common/file.cpp +++ b/src/common/file.cpp @@ -38,6 +38,7 @@ bool HdcFile::BeginTransfer(CtxFile *context, const string &command) { int argc = 0; bool ret = false; + StartTraceScope("HdcFile::BeginTransfer"); char **argv = Base::SplitCommandToArgs(command.c_str(), &argc); if (argc < CMD_ARG1_COUNT || argv == nullptr) { LogMsg(MSG_FAIL, "Transfer path split failed"); @@ -148,6 +149,7 @@ bool HdcFile::SetMasterParameters(CtxFile *context, const char *command, int arg void HdcFile::CheckMaster(CtxFile *context) { + StartTraceScope("HdcFile::CheckMaster"); if (context->fileModeSync) { string s = SerialStruct::SerializeToString(context->fileMode); SendToAnother(CMD_FILE_MODE, reinterpret_cast(const_cast(s.c_str())), s.size()); @@ -187,6 +189,7 @@ void HdcFile::TransferSummary(CtxFile *context) bool HdcFile::FileModeSync(const uint16_t cmd, uint8_t *payload, const int payloadSize) { + StartTraceScope("HdcFile::FileModeSync"); if (ctxNow.master) { WRITE_LOG(LOG_DEBUG, "FileModeSync master ctxNow.fileModeSync = %d size = %zu", ctxNow.fileModeSync, ctxNow.dirMode.size()); @@ -311,6 +314,7 @@ bool HdcFile::CommandDispatch(const uint16_t command, uint8_t *payload, const in { HdcTransferBase::CommandDispatch(command, payload, payloadSize); bool ret = true; + StartTraceScope("HdcFile::CommandDispatch"); switch (command) { case CMD_FILE_INIT: { // initial string s = string(reinterpret_cast(payload), payloadSize); diff --git a/src/common/session.cpp b/src/common/session.cpp index 58b88221..0d057852 100755 --- a/src/common/session.cpp +++ b/src/common/session.cpp @@ -95,6 +95,7 @@ bool HdcSessionBase::TryRemoveTask(HTaskInfo hTask) // remove step1 void HdcSessionBase::BeginRemoveTask(HTaskInfo hTask) { + StartTraceScope("HdcSessionBase::BeginRemoveTask"); if (hTask->taskStop || hTask->taskFree) { return; } @@ -105,6 +106,7 @@ void HdcSessionBase::BeginRemoveTask(HTaskInfo hTask) WRITE_LOG(LOG_INFO, "RemoveInstanceTask false taskType:%d channelId:%u", hTask->taskType, hTask->channelId); } auto taskClassDeleteRetry = [](uv_timer_t *handle) -> void { + StartTracePoint("HdcSessionBase::BeginRemoveTask: taskClassDeleteRetry"); HTaskInfo hTask = (HTaskInfo)handle->data; HdcSessionBase *thisClass = (HdcSessionBase *)hTask->ownerSessionClass; constexpr uint32_t count = 1000; @@ -123,6 +125,7 @@ void HdcSessionBase::BeginRemoveTask(HTaskInfo hTask) hTask = nullptr; } Base::TryCloseHandle((uv_handle_t *)handle, Base::CloseTimerCallback); + FinishTracePoint(); }; Base::TimerUvTask(hTask->runLoop, hTask, taskClassDeleteRetry, (GLOBAL_TIMEOUT * TIME_BASE) / UV_DEFAULT_INTERVAL); @@ -138,6 +141,7 @@ void HdcSessionBase::ClearOwnTasks(HSession hSession, const uint32_t channelIDIn // First case: normal task cleanup process (STOP Remove) // Second: The task is cleaned up, the session ends // Third: The task is cleaned up, and the session is directly over the session. + StartTraceScope("HdcSessionBase::ClearOwnTasks"); hSession->mapTaskMutex.lock(); map::iterator iter; for (iter = hSession->mapTask->begin(); iter != hSession->mapTask->end();) { @@ -175,6 +179,7 @@ void HdcSessionBase::ClearSessions() void HdcSessionBase::ReMainLoopForInstanceClear() { // reloop + StartTraceScope("HdcSessionBase::ReMainLoopForInstanceClear"); auto clearSessionsForFinish = [](uv_idle_t *handle) -> void { HdcSessionBase *thisClass = (HdcSessionBase *)handle->data; if (thisClass->sessionRef > 0) { @@ -560,6 +565,7 @@ void HdcSessionBase::FreeSessionContinue(HSession hSession) void HdcSessionBase::FreeSessionOpeate(uv_timer_t *handle) { + StartTraceScope("HdcSessionBase::FreeSessionOpeate"); HSession hSession = (HSession)handle->data; HdcSessionBase *thisClass = (HdcSessionBase *)hSession->classInstance; if (hSession->ref > 0) { @@ -597,6 +603,7 @@ void HdcSessionBase::FreeSessionOpeate(uv_timer_t *handle) void HdcSessionBase::FreeSession(const uint32_t sessionId) { + StartTraceScope("HdcSessionBase::FreeSession"); if (threadSessionMain != uv_thread_self()) { PushAsyncMessage(sessionId, ASYNC_FREE_SESSION, nullptr, 0); return; @@ -745,6 +752,7 @@ HTaskInfo HdcSessionBase::AdminTask(const uint8_t op, HSession hSession, const u int HdcSessionBase::SendByProtocol(HSession hSession, uint8_t *bufPtr, const int bufLen, bool echo ) { + StartTraceScope("HdcSessionBase::SendByProtocol"); if (hSession->isDead) { WRITE_LOG(LOG_WARN, "SendByProtocol session dead error"); return ERR_SESSION_NOFOUND; @@ -824,6 +832,7 @@ int HdcSessionBase::Send(const uint32_t sessionId, const uint32_t channelId, con } bool bufRet = false; do { + StartTracePoint("HdcSessionBase::Send memcpy_s PayloadHead + s"); if (memcpy_s(finayBuf, sizeof(PayloadHead), reinterpret_cast(&payloadHead), sizeof(PayloadHead))) { WRITE_LOG(LOG_WARN, "send copyhead err for dataSize:%d", dataSize); break; @@ -837,6 +846,7 @@ int HdcSessionBase::Send(const uint32_t sessionId, const uint32_t channelId, con WRITE_LOG(LOG_WARN, "send copyDatabuf err for dataSize:%d", dataSize); break; } + FinishTracePoint(); bufRet = true; } while (false); if (!bufRet) { @@ -853,6 +863,7 @@ int HdcSessionBase::Send(const uint32_t sessionId, const uint32_t channelId, con int HdcSessionBase::DecryptPayload(HSession hSession, PayloadHead *payloadHeadBe, uint8_t *encBuf) { + StartTraceScope("HdcSessionBase::DecryptPayload"); PayloadProtect protectBuf = {}; uint16_t headSize = ntohs(payloadHeadBe->headSize); int dataSize = ntohl(payloadHeadBe->dataSize); @@ -878,6 +889,7 @@ int HdcSessionBase::DecryptPayload(HSession hSession, PayloadHead *payloadHeadBe int HdcSessionBase::OnRead(HSession hSession, uint8_t *bufPtr, const int bufLen) { int ret = ERR_GENERIC; + StartTraceScope("HdcSessionBase::OnRead"); if (memcmp(bufPtr, PACKET_FLAG.c_str(), PACKET_FLAG.size())) { WRITE_LOG(LOG_FATAL, "PACKET_FLAG incorrect %x %x", bufPtr[0], bufPtr[1]); return ERR_BUF_CHECK; @@ -906,6 +918,7 @@ int HdcSessionBase::FetchIOBuf(HSession hSession, uint8_t *ioBuf, int read) HdcSessionBase *ptrConnect = (HdcSessionBase *)hSession->classInstance; int indexBuf = 0; int childRet = 0; + StartTraceScope("HdcSessionBase::FetchIOBuf"); if (read < 0) { constexpr int bufSize = 1024; char buf[bufSize] = { 0 }; diff --git a/src/common/transfer.cpp b/src/common/transfer.cpp index 737cc6a9..0e418b4b 100644 --- a/src/common/transfer.cpp +++ b/src/common/transfer.cpp @@ -61,6 +61,7 @@ int HdcTransferBase::SimpleFileIO(CtxFile *context, uint64_t index, uint8_t *sen uint8_t *buf = new uint8_t[bytes + payloadPrefixReserve](); CtxFileIO *ioContext = new CtxFileIO(); bool ret = false; + StartTraceScope("HdcTransferBase::SimpleFileIO"); while (true) { if (!buf || !ioContext || bytes < 0) { WRITE_LOG(LOG_DEBUG, "SimpleFileIO param check failed"); @@ -143,6 +144,7 @@ bool HdcTransferBase::SendIOPayload(CtxFile *context, uint64_t index, uint8_t *d uint8_t *sendBuf = data - payloadPrefixReserve; bool ret = false; + StartTraceScope("HdcTransferBase::SendIOPayload"); payloadHead.compressType = context->transferConfig.compressType; payloadHead.uncompressSize = dataSize; payloadHead.index = index; @@ -189,6 +191,7 @@ void HdcTransferBase::OnFileIO(uv_fs_t *req) CtxFile *context = reinterpret_cast(contextIO->context); HdcTransferBase *thisClass = (HdcTransferBase *)context->thisClass; uint8_t *bufIO = contextIO->bufIO; + StartTraceScope("HdcTransferBase::OnFileIO"); uv_fs_req_cleanup(req); while (true) { if (context->ioFinish) { @@ -255,6 +258,7 @@ void HdcTransferBase::OnFileOpen(uv_fs_t *req) { CtxFile *context = (CtxFile *)req->data; HdcTransferBase *thisClass = (HdcTransferBase *)context->thisClass; + StartTraceScope("HdcTransferBase::OnFileOpen"); uv_fs_req_cleanup(req); WRITE_LOG(LOG_DEBUG, "Filemod openfile:%s", context->localPath.c_str()); --thisClass->refCount; @@ -594,6 +598,7 @@ bool HdcTransferBase::RecvIOPayload(CtxFile *context, uint8_t *data, int dataSiz bool ret = false; SerialStruct::ParseFromString(pld, serialStrring); int clearSize = 0; + StartTraceScope("HdcTransferBase::RecvIOPayload"); if (pld.compressSize > 0) { switch (pld.compressType) { #ifdef HARMONY_PROJECT diff --git a/src/common/usb.cpp b/src/common/usb.cpp index e37c77f8..5f8ee741 100644 --- a/src/common/usb.cpp +++ b/src/common/usb.cpp @@ -75,6 +75,7 @@ int HdcUSBBase::SendUSBBlock(HSession hSession, uint8_t *data, const int length) { int childRet = 0; int ret = ERR_IO_FAIL; + StartTraceScope("HdcUSBBase::SendUSBBlock"); auto header = BuildPacketHeader(hSession->sessionId, USB_OPTION_HEADER, length); hSession->hUSB->lockSendUsbBlock.lock(); do { @@ -170,6 +171,7 @@ int HdcUSBBase::SendToHdcStream(HSession hSession, uv_stream_t *stream, uint8_t { int childRet = 0; HUSB hUSB = hSession->hUSB; + StartTraceScope("HdcUSBBase::SendToHdcStream: SendToStreamEx"); if (IsUsbPacketHeader(appendData, dataSize)) { return CheckPacketOption(hSession, appendData, dataSize); } diff --git a/src/daemon/daemon_usb.cpp b/src/daemon/daemon_usb.cpp index f0ebb123..da8a134a 100644 --- a/src/daemon/daemon_usb.cpp +++ b/src/daemon/daemon_usb.cpp @@ -297,6 +297,7 @@ int HdcDaemonUSB::SendUSBIOSync(HSession hSession, HUSB hMainUSB, const uint8_t int childRet = 0; int ret = ERR_IO_FAIL; int offset = 0; + StartTraceScope("HdcDaemonUSB::SendUSBIOSync"); while (modRunning && isAlive && !hSession->isDead) { childRet = write(bulkIn, const_cast(data) + offset, length - offset); if (childRet <= 0) { @@ -327,6 +328,7 @@ int HdcDaemonUSB::SendUSBIOSync(HSession hSession, HUSB hMainUSB, const uint8_t int HdcDaemonUSB::SendUSBRaw(HSession hSession, uint8_t *data, const int length) { HdcDaemon *daemon = (HdcDaemon *)hSession->classInstance; + StartTraceScope("SendUSBRaw: SendUSBIOSync"); std::unique_lock lock(mutexUsbFfs); ++hSession->ref; int ret = SendUSBIOSync(hSession, &usbHandle, data, length); @@ -356,6 +358,7 @@ void HdcDaemonUSB::OnSessionFreeFinally(const HSession hSession) HSession HdcDaemonUSB::PrepareNewSession(uint32_t sessionId, uint8_t *pRecvBuf, int recvBytesIO) { HdcDaemon *daemon = reinterpret_cast(clsMainBase); + StartTraceScope("HdcDaemonUSB::PrepareNewSession"); HSession hChildSession = daemon->MallocSession(false, CONN_USB, this, sessionId); if (!hChildSession) { return nullptr; @@ -389,6 +392,7 @@ int HdcDaemonUSB::DispatchToWorkThread(uint32_t sessionId, uint8_t *readBuf, int HSession hChildSession = nullptr; HdcDaemon *daemon = reinterpret_cast(clsMainBase); int childRet = RET_SUCCESS; + StartTraceScope("HdcDaemonUSB::DispatchToWorkThread"); if (sessionId == 0) { // hdc packet data sessionId = currentSessionId; @@ -508,6 +512,7 @@ int HdcDaemonUSB::LoopUSBRead(HUSB hUSB, int readMaxWanted) int ret = ERR_GENERIC; HdcDaemon *daemon = reinterpret_cast(clsMainBase); uv_buf_t iov; + StartTraceScope("HdcDaemonUSB::LoopUSBRead"); ctxRecv.data = hUSB; ctxRecv.bufSize = readMaxWanted; ctxRecv.req = {}; @@ -517,9 +522,11 @@ int HdcDaemonUSB::LoopUSBRead(HUSB hUSB, int readMaxWanted) ret = uv_fs_read(&daemon->loopMain, req, hUSB->bulkOut, &iov, 1, -1, OnUSBRead); if (ret < 0) { WRITE_LOG(LOG_FATAL, "uv_fs_read < 0"); + FinishTracePoint(); return ERR_API_FAIL; } ctxRecv.atPollQueue = true; + FinishTracePoint(); return RET_SUCCESS; }