ecmascript/compiler/compiler_log.cpp

/*
 * Copyright (c) 2022 Huawei Device Co., Ltd.
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at
 *
 *     http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */

#include "ecmascript/compiler/compiler_log.h"

namespace panda::ecmascript::kungfu {
CompilerLog::CompilerLog(const std::string &logOpt)
{
    outputCIR_ = (logOpt.find("cir") != std::string::npos) || (logOpt.find("0") != std::string::npos);
    outputLLIR_ = (logOpt.find("llir") != std::string::npos) || (logOpt.find("1") != std::string::npos);
    outputASM_ = (logOpt.find("asm") != std::string::npos) || (logOpt.find("2") != std::string::npos);
    outputType_ = (logOpt.find("type") != std::string::npos) || (logOpt.find("3") != std::string::npos);
    allMethod_ = logOpt.find("all") != std::string::npos;
    cerMethod_ = (logOpt.find("all") == std::string::npos) && (logOpt.find("cer") != std::string::npos);
    noneMethod_ = (logOpt.find("all") == std::string::npos) && (logOpt.find("cer") == std::string::npos);
}

void CompilerLog::SetMethodLog(const std::string &fileName,
                               const std::string &methodName, AotMethodLogList *logList)
{
    bool enableMethodLog = !NoneMethod();
    if (CertainMethod()) {
        enableMethodLog = logList->IncludesMethod(fileName, methodName);
    }
    SetEnableMethodLog(enableMethodLog);
}

void CompilerLog::SetStubLog(const std::string &stubName, MethodLogList *logList)
{
    bool enableMethodLog = !NoneMethod();
    if (CertainMethod()) {
        enableMethodLog = logList->IncludesMethod(stubName);
    }
    SetEnableMethodLog(enableMethodLog);
}

bool MethodLogList::IncludesMethod(const std::string &methodName) const
{
    bool empty = methodName.empty();
    bool found = methods_.find(methodName) != std::string::npos;
    return !empty && found;
}

bool AotMethodLogList::IncludesMethod(const std::string &fileName, const std::string &methodName) const
{
    if (fileMethods_.find(fileName) == fileMethods_.end()) {
        return false;
    }
    std::vector methodVector = fileMethods_.at(fileName);
    auto it = find(methodVector.begin(), methodVector.end(), methodName);
    return (it != methodVector.end());
}

std::vector<std::string> AotMethodLogList::spiltString(const std::string &str, const char ch)
{
    std::vector<std::string> vec {};
    std::istringstream sstr(str.c_str());
    std::string spilt;
    while (getline(sstr, spilt, ch)) {
        vec.emplace_back(spilt);
    }
    return vec;
}

void AotMethodLogList::ParseFileMethodsName(const std::string &logMethods)
{
    std::vector<std::string> fileVector = spiltString(logMethods, fileSplitSign);
    std::vector<std::string> itemVector;
    for (size_t index = 0; index < fileVector.size(); ++index) {
        itemVector = spiltString(fileVector[index], methodSplitSign);
        std::vector<std::string> methodVector(itemVector.begin() + 1, itemVector.end());
        fileMethods_[itemVector[0]] = methodVector;
    }
}

TimeScope::TimeScope(std::string name, std::string methodName, uint32_t methodOffset, CompilerLog* log)
    : ClockScope(), name_(std::move(name)), methodName_(std::move(methodName)), methodOffset_(methodOffset), log_(log)
{
    if (log_->GetEnableCompilerLogTime()) {
        if (log_->nameIndex_.find(name_) == log_->nameIndex_.end()) {
            log_->nameIndex_[name_] = log_->GetIndex();
        }
        startTime_ = ClockScope().GetCurTime();
    }
}

TimeScope::TimeScope(std::string name, CompilerLog* log)
    : ClockScope(), name_(std::move(name)), log_(log)
{
    if (log_->GetEnableCompilerLogTime()) {
        if (log_->nameIndex_.find(name_) == log_->nameIndex_.end()) {
            log_->nameIndex_[name_] = log_->GetIndex();
        }
        startTime_ = ClockScope().GetCurTime();
    }
}

TimeScope::~TimeScope()
{
    if (log_->GetEnableCompilerLogTime()) {
        timeUsed_ = ClockScope().GetCurTime() - startTime_;
        if (log_->CertainMethod() && log_->GetEnableMethodLog()) {
            LOG_COMPILER(INFO) << std::setw(PASS_LENS) << name_ << " " << std::setw(METHOD_LENS)
                               << GetShortName(methodName_) << " offset:" << std::setw(OFFSET_LENS) << methodOffset_
                               << " time used:" << std::setw(TIME_LENS) << timeUsed_ / MILLION_TIME << "ms";
        }
        std::string shortName = GetShortName(methodName_);
        log_->AddPassTime(name_, timeUsed_);
        log_->AddMethodTime(shortName, methodOffset_, timeUsed_);
    }
}

const std::string TimeScope::GetShortName(const std::string& methodName)
{
    std::string KeyStr = "@";
    if (methodName.find(KeyStr) != std::string::npos) {
        std::string::size_type index = methodName.find(KeyStr);
        std::string extracted = methodName.substr(0, index);
        return extracted;
    } else {
        return methodName;
    }
}

void CompilerLog::Print() const
{
    if (compilerLogTime_) {
        PrintTime();
    }
}

void CompilerLog::PrintPassTime() const
{
    double allPassTimeforAllMethods = 0;
    auto myMap = timePassMap_;
    auto myIndexMap = nameIndex_;
    std::multimap<int, std::string> PassTimeMap;
    for (auto it = myMap.begin(); it != myMap.end(); it++) {
        PassTimeMap.insert(make_pair(myIndexMap[it->first], it->first));
        allPassTimeforAllMethods += it->second;
    }
    for (auto [key, val] : PassTimeMap) {
        LOG_COMPILER(INFO) << std::setw(PASS_LENS) << val << " Total cost time is "<< std::setw(TIME_LENS)
                           << myMap[val] / MILLION_TIME << "ms " << "percentage:"
                           << std::fixed << std::setprecision(PERCENT_LENS)
                           << myMap[val] / allPassTimeforAllMethods * HUNDRED_TIME << "% ";
    }
}

void CompilerLog::PrintMethodTime() const
{
    double methodTotalTime = 0;
    auto myMap = timeMethodMap_;
    std::multimap<double, std::pair<uint32_t, std::string>> MethodTimeMap;
    std::map<std::pair<uint32_t, std::string>, double>::iterator it;
    for (it = myMap.begin(); it != myMap.end(); it++) {
        MethodTimeMap.insert(make_pair(it->second, it->first));
    }
    for (auto [key, val] : MethodTimeMap) {
        methodTotalTime += key;
    }
    for (auto [key, val] : MethodTimeMap) {
        LOG_COMPILER(INFO) << "method:" << std::setw(METHOD_LENS) << val.second
                           << " offset:" << std::setw(OFFSET_LENS) << val.first << " all pass cost time is "
                           << std::setw(TIME_LENS) << key / MILLION_TIME << "ms " << "percentage:" << std::fixed
                           << std::setprecision(PERCENT_LENS) << key / methodTotalTime * HUNDRED_TIME << "% ";
    }
    LOG_COMPILER(INFO) << "total compile time is " << std::setw(TIME_LENS) << methodTotalTime / MILLION_TIME << "ms ";
}

void CompilerLog::PrintTime() const
{
    LOG_COMPILER(INFO) << " ";
    PrintPassTime();
    LOG_COMPILER(INFO) << " ";
    PrintMethodTime();
}

void CompilerLog::AddMethodTime(const std::string& name, uint32_t id, double time)
{
    auto methodInfo = std::make_pair(id, name);
    timeMethodMap_[methodInfo] += time;
}

void CompilerLog::AddPassTime(const std::string& name, double time)
{
    timePassMap_[name] += time;
}

int CompilerLog::GetIndex()
{
    return (idx_++);
}

void PGOTypeLogList::CollectGateTypeLogInfo(GateRef gate, bool isBinOp)
{
    log_ += "[PGOTypePrinter] ";
    log_ += "gate id: "+ std::to_string(acc_.GetId(gate)) + ", ";
    EcmaOpcode ecmaOpcode = acc_.GetByteCodeOpcode(gate);
    log_ += "bytecode: " + GetEcmaOpcodeStr(ecmaOpcode);

    uint32_t pcOffset = acc_.TryGetPcOffset(gate);
    if (isBinOp) {
        const PGOSampleType *sampleType = acc_.TryGetPGOType(gate).GetPGOSampleType();
        if (sampleType->IsString()) {
            log_ += " [left type: string, right type: string]";
        } else if (sampleType->HasNumber()) {
            if (sampleType->IsInt()) {
                log_ += " [left type: int, right type: int]";
            } else {
                if (sampleType->IsIntOverFlow()) {
                    log_ += " [left type: int, right type: int]";
                } else if (sampleType->IsDouble()) {
                    log_ += " [left type: double, right type: double]";
                } else {
                    log_ += " [left type: number, right type: number]";
                }
            }
        } else {
            GateRef left = acc_.GetValueIn(gate, 0);
            GateRef right = acc_.GetValueIn(gate, 1);
            GateType leftType = acc_.GetGateType(left);
            GateType rightType = acc_.GetGateType(right);
            if (leftType.IsIntType()) {
                log_ += " [left type: int, ";
            } else if (leftType.IsDoubleType()) {
                log_ += " [left type: double, ";
            } else {
                log_ += " [left type: number, ";
            }
            if (rightType.IsIntType()) {
                log_ += "right type: int]";
            } else if (rightType.IsDoubleType()) {
                log_ += "right type: double]";
            } else {
                log_ += "right type: number]";
            }
        }
    } else {
        GateRef value = acc_.GetValueIn(gate, 0);
        GateType valueType = acc_.GetGateType(value);
        if (valueType.IsIntType()) {
            log_ += " [type: int]";
        } else if (valueType.IsDoubleType()) {
            log_ += " [type: double]";
        } else {
            log_ += " [type: number]";
        }
    }
    log_ += ", pcOffset: " + std::to_string(pcOffset);
    log_ += "\n[compiler] ";
}

void PGOTypeLogList::PrintPGOTypeLog()
{
    LOG_COMPILER(INFO) << log_;
}

} // namespace panda::ecmascript::kungfu