Ark运行时日志不打印问题分析报告

鸿蒙使小强 2023-03-13 17:39:41

1 关键字

ark; LOG_ECMA; 日志;

2 问题描述

开发板型号：rk3568

OH版本：OpenHarmony 3.1 Release

问题现象：hilog中搜不到 LOG_ECMA 的输出（ark/runtime_core/libpandabase/utils/logger.h）日志

测试步骤：

  1. 烧镜像
  2. 终端输入hilog | grep Ark
  3. eco跑一个demo

日志输出空

3 问题原因

3.1 正常机制

日志中出现如下格式的日志 ，有 Ark 函数名 行号

03900/Ace: [jsi_declarative_engine.cpp(PrintLog)-(0)] Ark ecmascript::GenerateProgram Line:77 GenerateProgram /data/storage/el1/bundle/com.example.entry/assets/js/MainAbility/app.abc

3.2 异常机制

Ark 关键字的日志为空

4 解决方案

通过下面方式可以看到ark的日志输出

方法一：

修改ark\runtime_core\libpandabase\utils\logger.h文件的WriteMobileLog方法，将is_mlog_opened_的判断去掉，is_mlog_opened_此时的值是false,在判断里面会直接return，不会执行后面的打印日志流程。

if (mlog_buf_print == nullptr || !is_mlog_opened_) {
    return;
}

改为

if (mlog_buf_print == nullptr) {
    return;
}

方法二：

注释源码里面所有的Logger::SetMobileLogOpenFlag(false);

按照上面的方法可以在全量日志里看到ark相关的日志

img

img

5 定位过程

  1. 根据LOG_ECMA查找LOG_ECMA的定义
    定义地方ark\js_runtime\ecmascript\ecma_macros.h
#define LOG_ECMA(type) \
LOG(type, ECMASCRIPT) << __func__ << " Line:" << __LINE__ << " "  // NOLINT(bugprone-lambda-function-name)

可以得出日志是以 方法名 Line：行号的 的形式输出。

  1. 再跟LOG到ark\runtime_core\libpandabase\utils\logger.h 文件中
    最后调用的是
#define _LOG(level, component, p)
panda::Logger::IsLoggingOnOrAbort(panda::Logger::Level::level, panda::Logger::Component::component) && panda::Logger::Message(panda::Logger::Level::level, panda::Logger::Component::component, p).GetStream()
  1. 跟踪上步中的Message对象
class Message {
    public:
        Message(Level level, Component component, bool print_system_error): 
        level_(level), 
        component_(component),print_system_error_(print_system_error)
    {
    }

    ~Message();

    std::ostream &GetStream()
    {
        return stream_;
    }

    private:
        Level level_;
        Component component_;
        bool print_system_error_;
        std::ostringstream stream_;

        NO_COPY_SEMANTIC(Message);
        NO_MOVE_SEMANTIC(Message);
};

Logger::Message::~Message()
{
    if (print_system_error_) {
        stream_ << ": " << os::Error(errno).ToString();
    }
   
    Logger::Log(level_, component_, stream_.str());
   
    if (level_ == Level::FATAL) {
        std::abort();
    }
}

在析构函数中看到了Logger::Log(level_, component_, stream_.str());

  1. 跟踪Logger::Log函数发现该函数中调用了WriteMobileLog方法。

  2. 跟踪WriteMobileLog方法

void WriteMobileLog(Level level, const char *component, const char *message)
    {
        if (mlog_buf_print == nullptr || !is_mlog_opened_) {
            return;
    }
    PandaLog2MobileLog mlog_level = PandaLog2MobileLog::UNKNOWN;
    switch (level) {
        case Level::DEBUG:
            mlog_level = PandaLog2MobileLog::DEBUG;
        break;
        case Level::INFO:
            mlog_level = PandaLog2MobileLog::INFO;
        break;
        case Level::ERROR:
            mlog_level = PandaLog2MobileLog::ERROR;
        break;
        case Level::FATAL:
            mlog_level = PandaLog2MobileLog::FATAL;
        break;
        case Level::WARNING:
            mlog_level = PandaLog2MobileLog::WARN;
        break;
        default:
        UNREACHABLE();
    }
    std::string panda_component = "Ark " + std::string(component);
    mlog_buf_print(LOG_ID_MAIN, mlog_level, panda_component.c_str(), "%s", message);
}
  • 有个判断条件 is_mlog_opened_ 日志控制开关
  • mlog_buf_print函数执行打印日志
  1. 跟踪mlog_buf_print赋值的地方
  • ark\runtime_core\libpandabase\utils\logger.h中SetMobileLogPrintEntryPointByPtr方法
  static void SetMobileLogPrintEntryPointByPtr(void *mlog_buf_print_ptr)
      {
          mlog_buf_print = reinterpret_cast<FUNC_MOBILE_LOG_PRINT>(mlog_buf_print_ptr);
      }
  • ark\js_runtime\ecmascript\napi\jsnapi.cpp中调用SetMobileLogPrintEntryPointByPtr方法的地方
bool JSNApi::CreateRuntime(const RuntimeOption &option)
{
    ...
  
    // Dfx
    base_options::Options baseOptions("");
    baseOptions.SetLogLevel(option.GetLogLevel());
    arg_list_t logComponents;
    logComponents.emplace_back("all");
    baseOptions.SetLogComponents(logComponents);
    Logger::Initialize(baseOptions);
    if (option.GetLogBufPrint() != nullptr) {
        Logger::SetMobileLogPrintEntryPointByPtr(reinterpret_cast<void *>(option.GetLogBufPrint()));
    }
    ...
  
    return true;
}
  • foundation\ace\ace_engine\frameworks\bridge\declarative_frontend\engine\jsi\ark\ark_js_runtime.cpp中调用SetLogBufPrint方法设置打印函数
bool ArkJSRuntime::Initialize(const std::string &libraryPath, bool isDebugMode)
{
    RuntimeOption option;
    option.SetGcType(RuntimeOption::GC_TYPE::GEN_GC);
    option.SetArkProperties(SystemProperties::GetArkProperties());
    const int64_t poolSize = 0x10000000;  // 256M
    option.SetGcPoolSize(poolSize);
    option.SetLogLevel(RuntimeOption::LOG_LEVEL::ERROR);
    option.SetLogBufPrint(print_);
    option.SetDebuggerLibraryPath(libraryPath);
    libPath_ = libraryPath;
    isDebugMode_ = isDebugMode;
  
    vm_ = JSNApi::CreateJSVM(option);
    return vm_ != nullptr;
}
  1. 设置的打印函数
//文件路径 
//foundation\ace\ace_engine\frameworks\bridge\declarative_frontend\engine\jsi\ark\ark_js_runtime.cpp
void ArkJSRuntime::SetLogPrint(LOG_PRINT out)
{
    print_ = out;
}

//文件路径 
//foundation\ace\ace_engine\frameworks\bridge\declarative_frontend\engine\jsi\jsi_declarative_engine.cpp
bool JsiDeclarativeEngineInstance::InitJsEnv(bool debuggerMode,
const std::unordered_map<std::string, void*>& extraNativeObject, const shared_ptr<JsRuntime>& runtime)
{
    ...
   
    runtime_->SetLogPrint(PrintLog);
   
    ...
}
   
int PrintLog(int id, int level, const char* tag, const char* fmt, const char* message)
{
    switch (JsLogLevel(level - 3)) {
        case JsLogLevel::INFO:
            LOGI("%{public}s::%{public}s", tag, message);
            break;
        case JsLogLevel::WARNING:
            LOGW("%{public}s::%{public}s", tag, message);
            break;
        case JsLogLevel::ERROR:
            LOGE("%{public}s::%{public}s", tag, message);
            break;
        case JsLogLevel::DEBUG:
            LOGD("%{public}s::%{public}s", tag, message);
            break;
        default:
            LOGF("%{public}s::%{public}s", tag, message);
            break;
    }
    return 0;
}

​ PrintLog中使用的打印方法是ACE子系统下的日志输出方式

  1. 以上逻辑分析完，日志打印流程正常，但Ark日志没有输出，返回第5步WriteMobileLog中去掉if判断条件中对is_mlog_opened_的判断，测试发现有Ark相应的日志输出。故is_mlog_opened_值被设置成了false。
    修改方法是可以直接去掉对is_mlog_opened_的判断，或者将is_mlog_opened_更改为false的地方注释调Logger::SetMobileLogOpenFlag(false);

6 知识分享

  • ACE子系统通过函数指针设置ark日志的打印方法调用ark日志的打印
...全文
2326 回复 打赏 收藏 转发到动态 举报
写回复
用AI写文章
回复
切换为时间正序
请发表友善的回复…
发表回复
ERROR日志打印导致CPU满载
描述 开发环境对一台测试节点进行压测时，由于参数配置错误导致请求没有业务处理直接报错。随即停止压测后登录测试机器排查日志，以外发现虽然已经没有请求到该节点，但应用依然在打印错误日志，并且看日志时间是在打印几分钟前请求的日志。 第一反应是异步打印的日志出现堆积，于是查看了该应用所在节点的物理资源，发现CPU已经满荷载，以及JVM触发了多次Full GC和OOM。 分析 复现 该节点重启后，以50TPS的速率故意发起错误请求的压测，果然稳定复现CPU满载的问题，因此盲猜是因为CPU满载导致异步日志打印速率慢，生
鸿蒙HarmonyOS应用开发之使用Node-API接口创建ArkTs运行时环境
开发者通过pthread_create创建新线程后，可以通过来创建一个新的ArkTs基础运行时环境，并通过该运行时环境加载ArkTs模块，目前仅支持在ArkTs模块中使用console接口打印日志，使用timer定时器功能。当使用结束后，开发者需要通过来销毁所创建的ArkTs基础运行时环境。
ARK服务器RCON命令整理
最近查了下ARK官方支持的rcon命令，简单做下整理： 先说下游戏里进入命令台 enablecheats AdminPassword ShowMyAdminManager 官方说游戏内ShowMyAdminManager显示的命令行都可以用，但是……还是说下我试着好使的吧 listplayers 在线用户列表 banplayer PlayerName 用户踢出服务器（应该是直接拉...
读驱动ARK之A盾代码的总结
某位大牛说过，玩驱动最快的方法是自己写个ARK。A盾是开源的一个功能算是比较多的ARK，对木马，病毒在内核层还是可以拦截的。目前市面上的主动防御，杀毒软件的思路也是这样。但是，毕竟开源的，很多功能考虑的实现很浅，木有在内核里面深层次拦截。 它的开源的版本功能如下图 下载链接：   http://www.3600safe.com/?post=1     下面对开源代码的功能实现做简单的...
linux下delete释放不了内存,c++delete后虚拟内存不降的原因(疑似内存泄漏)
2017年末，手Q春节红包项目期间，为保障活动期间服务正常稳定，我对性能不佳的Ark Server进行了改造和重写。重编发布一段时间后，结果发现新发布的Svr的机器内存一直在上涨。如下图示：内存增长趋势图观察后，第一反应是完了，一定存在内存泄漏。花了3、4天时间，使用各种办法进行定位，一无所获。后来无意中在SPP日志中发现了端倪，日志中一直打印tcp socket[%d] user check p...
OpenHarmony开发者社区

517

社区成员

1,832

社区内容

发帖
与我相关
我的任务
社区描述
OpenHarmony开发者社区
其他 企业社区
社区管理员
  • csdnsqst0025
  • shewaliujingli
  • BaoWei
加入社区
  • 近7日
  • 近30日
  • 至今

加载中

查看更多榜单

试试用AI创作助手写篇文章吧

+ 用AI写文章