From bba1f14b6c1017ec622d198863c42d343752fc1c Mon Sep 17 00:00:00 2001
From: chenqy930 <chenqiuyao@huawei.com>
Date: Wed, 2 Aug 2023 17:25:13 +0800
Subject: [PATCH 1/4] Add perf option for es2abc

Change-Id: I70f8ddb6a13bb758cad4d291d74efea08606c218
Signed-off-by: chenqy930 <chenqiuyao@huawei.com>
---
 es2panda/BUILD.gn                       |   1 +
 es2panda/aot/emitFiles.cpp              |   7 ++
 es2panda/aot/main.cpp                   |  11 ++
 es2panda/aot/options.cpp                |  10 ++
 es2panda/aot/options.h                  |   6 +
 es2panda/compiler/core/compileQueue.cpp |   8 ++
 es2panda/es2panda.cpp                   |  42 ++++---
 es2panda/es2panda.h                     |   3 +-
 es2panda/util/timers.cpp                | 157 ++++++++++++++++++++++++
 es2panda/util/timers.h                  | 102 +++++++++++++++
 10 files changed, 330 insertions(+), 17 deletions(-)
 create mode 100644 es2panda/util/timers.cpp
 create mode 100644 es2panda/util/timers.h

diff --git a/es2panda/BUILD.gn b/es2panda/BUILD.gn
index 1129c59f5a..e81e9887e9 100644
--- a/es2panda/BUILD.gn
+++ b/es2panda/BUILD.gn
@@ -257,6 +257,7 @@ es2panda_src = [
   "util/patchFix.cpp",
   "util/moduleHelpers.cpp",
   "util/symbolTable.cpp",
+  "util/timers.cpp",
   "util/ustring.cpp",
   "util/workerQueue.cpp",
   "util/commonUtil.cpp",
diff --git a/es2panda/aot/emitFiles.cpp b/es2panda/aot/emitFiles.cpp
index f1f5a35979..1e4193bbdd 100644
--- a/es2panda/aot/emitFiles.cpp
+++ b/es2panda/aot/emitFiles.cpp
@@ -21,6 +21,7 @@
 #include <es2panda.h>
 #include <protobufSnapshotGenerator.h>
 #include <util/helpers.h>
+#include <util/timers.h>
 
 namespace panda::es2panda::aot {
 void EmitFileQueue::ScheduleEmitCacheJobs(EmitMergedAbcJob *emitMergedAbcJob)
@@ -80,6 +81,7 @@ void EmitFileQueue::Schedule()
 
 void EmitSingleAbcJob::Run()
 {
+    es2panda::util::Timer::timerStart(util::EVENT_EMIT_SINGLE_PROGRAM, outputFileName_);
     if (!panda::pandasm::AsmEmitter::Emit(panda::os::file::File::GetExtendedFilePath(outputFileName_), *prog_, statp_,
         nullptr, true, nullptr, targetApiVersion_)) {
         throw Error(ErrorType::GENERIC, "Failed to emit " + outputFileName_ + ", error: " +
@@ -88,10 +90,12 @@ void EmitSingleAbcJob::Run()
     for (auto *dependant : dependants_) {
         dependant->Signal();
     }
+    es2panda::util::Timer::timerEnd(util::EVENT_EMIT_SINGLE_PROGRAM, outputFileName_);
 }
 
 void EmitMergedAbcJob::Run()
 {
+    es2panda::util::Timer::timerStart(util::EVENT_EMIT_MERGED_PROGRAM, "");
     std::vector<panda::pandasm::Program*> progs;
     progs.reserve(progsInfo_.size());
     for (const auto &info: progsInfo_) {
@@ -104,6 +108,7 @@ void EmitMergedAbcJob::Run()
     for (auto *dependant : dependants_) {
         dependant->Signal();
     }
+    es2panda::util::Timer::timerEnd(util::EVENT_EMIT_MERGED_PROGRAM, "");
 
     if (!success) {
         throw Error(ErrorType::GENERIC, "Failed to emit " + outputFileName_ + ", error: " +
@@ -121,7 +126,9 @@ void EmitCacheJob::Run()
 {
     std::unique_lock<std::mutex> lock(m_);
     cond_.wait(lock, [this] { return dependencies_ == 0; });
+    es2panda::util::Timer::timerStart(util::EVENT_EMIT_CACHE_FILE, outputProtoName_);
     panda::proto::ProtobufSnapshotGenerator::UpdateCacheFile(progCache_, outputProtoName_);
+    es2panda::util::Timer::timerEnd(util::EVENT_EMIT_CACHE_FILE, outputProtoName_);
 }
 
 }  // namespace panda::es2panda::util
diff --git a/es2panda/aot/main.cpp b/es2panda/aot/main.cpp
index efa30fbaa2..495a28f394 100644
--- a/es2panda/aot/main.cpp
+++ b/es2panda/aot/main.cpp
@@ -28,6 +28,7 @@
 #include <util/dumper.h>
 #include <util/moduleHelpers.h>
 #include <util/programCache.h>
+#include <util/timers.h>
 #include <util/workerQueue.h>
 
 namespace panda::es2panda::aot {
@@ -246,6 +247,7 @@ int Run(int argc, const char **argv)
         return 0;
     }
 
+    es2panda::util::Timer::timerStart(util::EVENT_TOTAL, "");
     if (options->CompilerOptions().bcVersion || options->CompilerOptions().bcMinVersion) {
         std::string version = options->CompilerOptions().bcVersion ?
             panda::panda_file::GetVersion(panda::panda_file::version) :
@@ -258,6 +260,7 @@ int Run(int argc, const char **argv)
     panda::ArenaAllocator allocator(panda::SpaceType::SPACE_TYPE_COMPILER, nullptr, true);
 
     Compiler::SetExpectedProgsCount(options->CompilerOptions().sourceFiles.size());
+    es2panda::util::Timer::timerStart(util::EVENT_COMPILE, "");
     int ret = Compiler::CompileFiles(options->CompilerOptions(), programsInfo, &allocator);
     if (options->ParseOnly()) {
         return ret;
@@ -268,7 +271,9 @@ int Run(int argc, const char **argv)
             options->CompilerOptions(), programsInfo, &allocator);
         Compiler::SetExpectedProgsCount(Compiler::GetExpectedProgsCount() + 1);
     }
+    es2panda::util::Timer::timerEnd(util::EVENT_COMPILE, "");
 
+    es2panda::util::Timer::timerStart(util::EVENT_EMIT_ABC, "");
     // A mapping of program to its records which are resolved and collected as valid dependencies.
     std::map<std::string, std::unordered_set<std::string>> resolvedDepsRelation {};
 
@@ -280,6 +285,12 @@ int Run(int argc, const char **argv)
     if (!GenerateAbcFiles(programsInfo, options, Compiler::GetExpectedProgsCount(), resolvedDepsRelation)) {
         return 1;
     }
+    es2panda::util::Timer::timerEnd(util::EVENT_EMIT_ABC, "");
+
+    es2panda::util::Timer::timerEnd(util::EVENT_TOTAL, "");
+    if (!options->PerfFile().empty()) {
+        es2panda::util::Timer::PrintTimers();
+    }
 
     return 0;
 }
diff --git a/es2panda/aot/options.cpp b/es2panda/aot/options.cpp
index 45ee9f75cb..0fbf139899 100644
--- a/es2panda/aot/options.cpp
+++ b/es2panda/aot/options.cpp
@@ -33,6 +33,7 @@
 
 #include "mergeProgram.h"
 #include "util/helpers.h"
+#include "util/timers.h"
 #include "utils/pandargs.h"
 
 namespace panda::es2panda::aot {
@@ -336,6 +337,8 @@ bool Options::Parse(int argc, const char **argv)
     panda::PandArg<std::string> opCacheFile("cache-file", "", "cache file for incremental compile");
     panda::PandArg<std::string> opNpmModuleEntryList("npm-module-entry-list", "", "entry list file for module compile");
     panda::PandArg<bool> opMergeAbc("merge-abc", false, "Compile as merge abc");
+    panda::PandArg<std::string> opPerfFile("perf-file", "perf.txt", "Specify the file path to dump time consuming data"\
+        " during compilation process, default to 'perf.txt' in the current directory");
     panda::PandArg<bool> opuseDefineSemantic("use-define-semantic", false, "Compile ts class fields "\
         "in accordance with ECMAScript2022");
 
@@ -413,6 +416,7 @@ bool Options::Parse(int argc, const char **argv)
     argparser_->Add(&opCacheFile);
     argparser_->Add(&opNpmModuleEntryList);
     argparser_->Add(&opMergeAbc);
+    argparser_->Add(&opPerfFile);
     argparser_->Add(&opuseDefineSemantic);
     argparser_->Add(&opBranchElimination);
     argparser_->Add(&opOptTryCatchFunc);
@@ -593,6 +597,12 @@ bool Options::Parse(int argc, const char **argv)
         options_ |= OptionFlags::SIZE_PCT_STAT;
     }
 
+    perfFile_ = "";
+    if (opPerfFile.WasSet()) {
+        perfFile_ = opPerfFile.GetValue().empty() ? opPerfFile.GetDefaultValue() : opPerfFile.GetValue();
+    }
+    es2panda::util::Timer::InitializeTimer(perfFile_);
+
     compilerOptions_.recordSource = opRecordSource.GetValue();
     compilerOptions_.enableAbcInput = opEnableAbcInput.GetValue();
     compilerOptions_.dumpAsmProgram = opDumpAsmProgram.GetValue();
diff --git a/es2panda/aot/options.h b/es2panda/aot/options.h
index 65debf3b21..5d26ec2d7d 100644
--- a/es2panda/aot/options.h
+++ b/es2panda/aot/options.h
@@ -133,6 +133,11 @@ public:
         return outputFiles_;
     }
 
+    std::string PerfFile() const
+    {
+        return perfFile_;
+    }
+
     bool CollectInputFilesFromFileList(const std::string &input, const std::string &inputExtension);
     bool CollectInputFilesFromFileDirectory(const std::string &input, const std::string &extension);
     void ParseCacheFileOption(const std::string &cacheInput);
@@ -164,6 +169,7 @@ private:
     std::string npmModuleEntryList_;
     std::vector<es2panda::SourceFile> sourceFiles_;
     std::unordered_map<std::string, std::string> outputFiles_;
+    std::string perfFile_;
 };
 }  // namespace panda::es2panda::aot
 
diff --git a/es2panda/compiler/core/compileQueue.cpp b/es2panda/compiler/core/compileQueue.cpp
index 9bda1c8bd9..a8c14128b7 100644
--- a/es2panda/compiler/core/compileQueue.cpp
+++ b/es2panda/compiler/core/compileQueue.cpp
@@ -28,6 +28,7 @@
 #include <util/commonUtil.h>
 #include <util/dumper.h>
 #include <util/helpers.h>
+#include <util/timers.h>
 
 namespace panda::es2panda::compiler {
 
@@ -101,6 +102,7 @@ void CompileFileJob::Run()
 {
     std::stringstream ss;
     std::string buffer;
+    es2panda::util::Timer::timerStart(util::EVENT_READ_INPUT_AND_CACHE, src_->fileName);
     if (!src_->fileName.empty() && src_->isSourceMode) {
         if (!util::Helpers::ReadFileToBuffer(src_->fileName, ss)) {
             return;
@@ -108,10 +110,13 @@ void CompileFileJob::Run()
         buffer = ss.str();
         src_->source = buffer;
         if (RetrieveProgramFromCacheFiles(buffer)) {
+            es2panda::util::Timer::timerEnd(util::EVENT_READ_INPUT_AND_CACHE, src_->fileName);
             return;
         }
     }
+    es2panda::util::Timer::timerEnd(util::EVENT_READ_INPUT_AND_CACHE, src_->fileName);
 
+    es2panda::util::Timer::timerStart(util::EVENT_COMPILE_FILE, src_->fileName);
     es2panda::Compiler compiler(src_->scriptExtension, options_->functionThreadCount);
     if (!src_->isSourceMode) {
         compiler.AbcToAsmProgram(src_->fileName, *options_, progsInfo_, allocator_);
@@ -121,7 +126,9 @@ void CompileFileJob::Run()
     if (prog == nullptr) {
         return;
     }
+    es2panda::util::Timer::timerEnd(util::EVENT_COMPILE_FILE, src_->fileName);
 
+    es2panda::util::Timer::timerStart(util::EVENT_OPTIMIZE_PROGRAM, src_->fileName);
     bool requireOptimizationAfterAnalysis = false;
     // When cross-program optimizations are required, skip program-local optimization at this stage
     // and perform it later after the analysis of all programs has been completed
@@ -133,6 +140,7 @@ void CompileFileJob::Run()
             util::Helpers::OptimizeProgram(prog, src_->fileName);
         }
     }
+    es2panda::util::Timer::timerEnd(util::EVENT_OPTIMIZE_PROGRAM, src_->fileName);
 
     {
         std::unique_lock<std::mutex> lock(global_m_);
diff --git a/es2panda/es2panda.cpp b/es2panda/es2panda.cpp
index 18c1c24eb9..453276d184 100644
--- a/es2panda/es2panda.cpp
+++ b/es2panda/es2panda.cpp
@@ -25,6 +25,7 @@
 #include <typescript/checker.h>
 #include <util/commonUtil.h>
 #include <util/helpers.h>
+#include <util/timers.h>
 
 #include <iostream>
 
@@ -125,6 +126,7 @@ panda::pandasm::Program *Compiler::Compile(const SourceFile &input, const Compil
     }
 
     try {
+        es2panda::util::Timer::timerStart(util::EVENT_PARSE, fname);
         auto ast = parser_->Parse(input, options);
         ast.Binder()->SetProgram(&ast);
 
@@ -132,30 +134,18 @@ panda::pandasm::Program *Compiler::Compile(const SourceFile &input, const Compil
             std::cout << ast.Dump() << std::endl;
         }
 
-        if (ast.Extension() == ScriptExtension::TS && options.enableTypeCheck) {
-            ArenaAllocator localAllocator(SpaceType::SPACE_TYPE_COMPILER, nullptr, true);
-            auto checker = std::make_unique<checker::Checker>(&localAllocator, ast.Binder());
-            checker->StartChecker();
-        }
-
-        if (ast.Extension() == ScriptExtension::TS) {
-            transformer_->Transform(&ast);
-            ast.Binder()->IdentifierAnalysis(binder::ResolveBindingFlags::TS_AFTER_TRANSFORM);
-            if (options.dumpTransformedAst) {
-                std::cout << ast.Dump() << std::endl;
-            }
-            if (options.checkTransformedAstStructure) {
-                transformer_->CheckTransformedAstStructure(&ast);
-            }
-        }
+        ProcessAstForTS(&ast, options);
 
         if (options.parseOnly) {
             return nullptr;
         }
+        es2panda::util::Timer::timerEnd(util::EVENT_PARSE, fname);
 
+        es2panda::util::Timer::timerStart(util::EVENT_COMPILE_TO_PROGRAM, fname);
         std::string debugInfoSourceFile = options.debugInfoSourceFile.empty() ?
                                           sourcefile : options.debugInfoSourceFile;
         auto *prog = compiler_->Compile(&ast, options, debugInfoSourceFile, pkgName);
+        es2panda::util::Timer::timerEnd(util::EVENT_COMPILE_TO_PROGRAM, fname);
 
         CleanPatchFixHelper(patchFixHelper);
         return prog;
@@ -277,4 +267,24 @@ panda::pandasm::Program *Compiler::CompileFile(const CompilerOptions &options, S
     return program;
 }
 
+void Compiler::ProcessAstForTS(parser::Program *ast, const es2panda::CompilerOptions &options)
+{
+    if (ast->Extension() == ScriptExtension::TS && options.enableTypeCheck) {
+        ArenaAllocator localAllocator(SpaceType::SPACE_TYPE_COMPILER, nullptr, true);
+        auto checker = std::make_unique<checker::Checker>(&localAllocator, ast->Binder());
+        checker->StartChecker();
+    }
+
+    if (ast->Extension() == ScriptExtension::TS) {
+        transformer_->Transform(ast);
+        ast->Binder()->IdentifierAnalysis(binder::ResolveBindingFlags::TS_AFTER_TRANSFORM);
+        if (options.dumpTransformedAst) {
+            std::cout << ast->Dump() << std::endl;
+        }
+        if (options.checkTransformedAstStructure) {
+            transformer_->CheckTransformedAstStructure(ast);
+        }
+    }
+}
+
 }  // namespace panda::es2panda
diff --git a/es2panda/es2panda.h b/es2panda/es2panda.h
index 8cc78c0147..03bf315a22 100644
--- a/es2panda/es2panda.h
+++ b/es2panda/es2panda.h
@@ -36,6 +36,7 @@ struct PkgInfo;
 
 namespace parser {
 class ParserImpl;
+class Program;
 class Transformer;
 enum class ScriptKind;
 }  // namespace parser
@@ -202,7 +203,7 @@ public:
                                      util::SymbolTable *symbolTable = nullptr);
     panda::pandasm::Program *CompileFile(const CompilerOptions &options, SourceFile *src,
                                          util::SymbolTable *symbolTable);
-
+    void ProcessAstForTS(parser::Program *ast, const es2panda::CompilerOptions &options);
     static int CompileFiles(CompilerOptions &options,
         std::map<std::string, panda::es2panda::util::ProgramCache*> &progsInfo, panda::ArenaAllocator *allocator);
 
diff --git a/es2panda/util/timers.cpp b/es2panda/util/timers.cpp
new file mode 100644
index 0000000000..4fd2c83ceb
--- /dev/null
+++ b/es2panda/util/timers.cpp
@@ -0,0 +1,157 @@
+/*
+ * Copyright (c) 2024 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 "os/file.h"
+#include "timers.h"
+
+#include <algorithm>
+#include <cerrno>
+#include <cstring>
+#include <fstream>
+#include <iomanip>
+#include <iostream>
+#include <sstream>
+
+namespace panda::es2panda::util {
+TimeStartFunc Timer::timerStart;
+TimeEndFunc Timer::timerEnd;
+std::unordered_map<std::string_view, TimeRecord> Timer::timers_;
+std::vector<std::string_view> Timer::events_;
+std::mutex Timer::mutex_;
+std::string Timer::perfFile_;
+
+void Timer::InitializeTimer(std::string &perfFile)
+{
+    if (!perfFile.empty()) {
+        Timer::timerStart = Timer::TimerStartImpl;
+        Timer::timerEnd = Timer::TimerEndImpl;
+        perfFile_ = perfFile;
+    } else {
+        Timer::timerStart = Timer::TimerStartDoNothing;
+        Timer::timerEnd = Timer::TimerEndDoNothing;
+    }
+}
+
+void WriteFile(std::stringstream &ss, std::string &perfFile)
+{
+    std::ofstream fs;
+    fs.open(panda::os::file::File::GetExtendedFilePath(perfFile));
+    if (!fs.is_open()) {
+        std::cerr << "Failed to open perf file: " << perfFile << ". Errro: " << std::strerror(errno) << std::endl;
+        return;
+    }
+    fs << ss.str();
+    fs.close();
+}
+
+bool DescentComparator(std::pair<std::string, double> p1, std::pair<std::string, double> p2)
+{
+    return p1.second > p2.second;
+}
+
+void Timer::PrintTimers()
+{
+    std::stringstream ss;
+    ss << "------------- Compilation time consumption in milliseconds: -------------" << std::endl;
+    ss << "Note: When compiling multiple files in parallel, " <<
+          "we will track the time consumption of each file individually. The output will aggregate these times, " <<
+          "potentially resulting in a total time consumption greater than the sum of individual file times." <<
+          std::endl << std::endl;
+
+    std::vector<std::string> summedUpTimeString;
+    ss << "------------- Compilation time consumption of each file: ----------------" << std::endl;
+
+    for (auto &event: events_) {
+        auto &timeRecord = timers_.at(event);
+        auto formattedEvent =
+            std::string(timeRecord.level, ' ') + std::string(timeRecord.level, '#') + std::string(event);
+
+        double eventTime = 0.0;
+        std::vector<std::pair<std::string, double>> eachFileTime;
+        for (auto &[file, timePointRecord] : timeRecord.timePoints) {
+            auto t = std::chrono::duration_cast<std::chrono::milliseconds>(
+                timePointRecord.endTime - timePointRecord.startTime).count();
+            eventTime += t;
+            if (!file.empty()) {
+                eachFileTime.push_back(std::pair(file, t));
+            }
+        }
+
+        // print each file time consumption in descending order
+        if (!eachFileTime.empty()) {
+            std::sort(eachFileTime.begin(), eachFileTime.end(), DescentComparator);
+            ss << formattedEvent << ", time consumption of each file:" << std::endl;
+        }
+        for (auto &pair : eachFileTime) {
+            if (!pair.first.empty()) {
+                ss << pair.first << ": " << pair.second << " ms" <<std::endl;
+            }
+        }
+
+        // collect the sum of each file's time consumption
+        std::stringstream eventSummedUpTimeStream;
+        eventSummedUpTimeStream << formattedEvent << ": " << eventTime << " ms";
+        summedUpTimeString.push_back(eventSummedUpTimeStream.str());
+    }
+    ss << "------------- Compilation time consumption summed up: -------------------" << std::endl;
+    for (auto &str: summedUpTimeString) {
+        ss << str << std::endl;
+    }
+    ss << "-------------------------------------------------------------------------" << std::endl;
+    WriteFile(ss, perfFile_);
+}
+
+void Timer::TimerStartImpl(const std::string_view event, std::string fileName)
+{
+    TimePointRecord tpr;
+    tpr.startTime = std::chrono::steady_clock::now();
+    int level = 0;
+    try {
+        level = eventMap.at(event);
+    } catch (std::exception &error) {
+        std::cerr << "Undefiend event: " << event << ". Please check!" << std::endl;
+    }
+
+    std::unique_lock<std::mutex> lock(mutex_);
+    auto iter = timers_.find(event);
+    if (iter != timers_.end()) {
+        iter->second.timePoints.emplace(fileName, tpr);
+    } else {
+        TimeRecord tr;
+        tr.timePoints.emplace(fileName, tpr);
+        tr.event = event;
+        tr.level = level;
+
+        timers_.emplace(event, tr);
+        events_.push_back(event);
+    }
+}
+
+void Timer::TimerEndImpl(const std::string_view event, std::string fileName)
+{
+    auto endTime = std::chrono::steady_clock::now();
+
+    std::unique_lock<std::mutex> lock(mutex_);
+    try {
+        auto &timeRecord = timers_.at(event);
+        auto &timePoint = timeRecord.timePoints.at(fileName);
+        timePoint.endTime = endTime;
+    } catch (std::exception &error) {
+        std::cerr << "Event " << event << " and file " << fileName <<
+            " start timer not found in records, skip record end time!" << std::endl;
+    }
+}
+
+}  // namespace panda::es2panda::util
diff --git a/es2panda/util/timers.h b/es2panda/util/timers.h
new file mode 100644
index 0000000000..56a9906314
--- /dev/null
+++ b/es2panda/util/timers.h
@@ -0,0 +1,102 @@
+/*
+ * Copyright (c) 2024 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.
+ */
+
+#ifndef ES2PANDA_UTIL_TIMERS_H
+#define ES2PANDA_UTIL_TIMERS_H
+
+#include <chrono>
+#include <mutex>
+#include <string>
+#include <string_view>
+#include <unordered_map>
+#include <vector>
+
+namespace panda::es2panda::util {
+// Event list
+constexpr std::string_view EVENT_TOTAL = "Total";
+constexpr std::string_view EVENT_COMPILE = "Compile";
+constexpr std::string_view EVENT_EMIT_ABC = "Emit abc";
+constexpr std::string_view EVENT_READ_INPUT_AND_CACHE = "Read input and cache";
+constexpr std::string_view EVENT_COMPILE_FILE = "Compile file";
+constexpr std::string_view EVENT_OPTIMIZE_PROGRAM = "Optimize program";
+constexpr std::string_view EVENT_PARSE = "Parse";
+constexpr std::string_view EVENT_COMPILE_TO_PROGRAM = "Compile to program";
+constexpr std::string_view EVENT_EMIT_SINGLE_PROGRAM = "Emit single program";
+constexpr std::string_view EVENT_EMIT_MERGED_PROGRAM = "Emit merged program";
+constexpr std::string_view EVENT_EMIT_CACHE_FILE = "Emit cache file";
+
+// Event level, indicating the level of an event, where each event is a sub-event of the nearest preceding level event.
+// The top-level event's level is 0
+enum EventLevel {
+    ZERO = 0,
+    FIRST,
+    SECOND,
+    THIRD
+};
+
+// Holds pairs of {event, level} according to the order during compilation process.
+// When adding new events later, please add them in the compilation order for ease of reading and maintenance.
+const std::unordered_map<std::string_view, EventLevel> eventMap = {
+    { EVENT_TOTAL, EventLevel::ZERO },
+    { EVENT_COMPILE, EventLevel::FIRST },
+    { EVENT_READ_INPUT_AND_CACHE, EventLevel::SECOND },
+    { EVENT_COMPILE_FILE, EventLevel::SECOND },
+    { EVENT_PARSE, EventLevel::THIRD },
+    { EVENT_COMPILE_TO_PROGRAM, EventLevel::THIRD },
+    { EVENT_OPTIMIZE_PROGRAM, EventLevel::SECOND },
+    { EVENT_EMIT_ABC, EventLevel::FIRST },
+    { EVENT_EMIT_SINGLE_PROGRAM, EventLevel::SECOND },
+    { EVENT_EMIT_MERGED_PROGRAM, EventLevel::SECOND },
+    { EVENT_EMIT_CACHE_FILE, EventLevel::SECOND },
+};
+
+typedef void (*TimeStartFunc)(const std::string_view event, std::string fileName);
+typedef void (*TimeEndFunc)(const std::string_view event, std::string fileName);
+typedef std::chrono::time_point<std::chrono::steady_clock> TimePoint;
+
+struct TimePointRecord {
+    TimePoint startTime;
+    TimePoint endTime;
+};
+
+struct TimeRecord {
+    std::unordered_map<std::string, TimePointRecord> timePoints;  // pair of {fileName, TimePointRecord}
+    std::string event;
+    int level;
+};
+
+class Timer {
+public:
+    static void InitializeTimer(std::string &perfFile);
+    static void PrintTimers();
+
+    static TimeStartFunc timerStart;
+    static TimeEndFunc timerEnd;
+
+private:
+    static void TimerStartImpl(const std::string_view event, std::string fileName = "");
+    static void TimerEndImpl(const std::string_view event, std::string fileName = "");
+    static void TimerStartDoNothing(const std::string_view event, std::string fileName = "") {}
+    static void TimerEndDoNothing(const std::string_view event, std::string fileName = "") {}
+
+    static std::unordered_map<std::string_view, TimeRecord> timers_;  // pair of {event, TimeRecord}
+    static std::vector<std::string_view> events_;
+    static std::mutex mutex_;
+    static std::string perfFile_;
+};
+
+}  // namespace panda::es2panda::util
+
+#endif  // ES2PANDA_UTIL_TIMERS_H
-- 
Gitee


From 75857a1e6e12eacb7f9eb37fa2a5b337e1d353a2 Mon Sep 17 00:00:00 2001
From: c00513733 <chenqiuyao@huawei.com>
Date: Sat, 15 Jun 2024 17:18:56 +0800
Subject: [PATCH 2/4] Add perf for patchfix

Signed-off-by: c00513733 <chenqiuyao@huawei.com>
Change-Id: Ib35d5d21d27a2f31651cf5d7c83d687fcb9cac9b
---
 es2panda/compiler/core/emitter/emitter.cpp |  4 ++++
 es2panda/util/patchFix.cpp                 |  7 +++++++
 es2panda/util/symbolTable.cpp              | 10 ++++++++++
 es2panda/util/timers.h                     | 21 ++++++++++++++++++---
 4 files changed, 39 insertions(+), 3 deletions(-)

diff --git a/es2panda/compiler/core/emitter/emitter.cpp b/es2panda/compiler/core/emitter/emitter.cpp
index 6304c14094..4fc70013d1 100644
--- a/es2panda/compiler/core/emitter/emitter.cpp
+++ b/es2panda/compiler/core/emitter/emitter.cpp
@@ -33,6 +33,7 @@
 #include <macros.h>
 #include <parser/program/program.h>
 #include <util/helpers.h>
+#include <util/timers.h>
 
 #include <string>
 #include <string_view>
@@ -69,9 +70,12 @@ void FunctionEmitter::Generate(util::PatchFix *patchFixHelper)
     GenLiteralBuffers();
     GenFunctionSource();
     GenConcurrentFunctionModuleRequests();
+
+    es2panda::util::Timer::timerStart(util::PATCH_FIX_DUMP_FUNCTION_INFO, std::string(pg_->Binder()->Program()->SourceFile()));
     if (patchFixHelper != nullptr) {
         patchFixHelper->ProcessFunction(pg_, func_, literalBuffers_);
     }
+    es2panda::util::Timer::timerEnd(util::PATCH_FIX_DUMP_FUNCTION_INFO, std::string(pg_->Binder()->Program()->SourceFile()));
 }
 
 const ArenaSet<util::StringView> &FunctionEmitter::Strings() const
diff --git a/es2panda/util/patchFix.cpp b/es2panda/util/patchFix.cpp
index 0940e77046..5cf12225c3 100644
--- a/es2panda/util/patchFix.cpp
+++ b/es2panda/util/patchFix.cpp
@@ -14,11 +14,13 @@
  */
 
 #include "patchFix.h"
+#include "timers.h"
 #include <binder/binder.h>
 #include <binder/scope.h>
 #include <binder/variable.h>
 #include <compiler/core/pandagen.h>
 #include <ir/expressions/literal.h>
+#include <parser/program/program.h>
 
 #include <fstream>
 #include <iostream>
@@ -616,6 +618,7 @@ void PatchFix::HandleFunction(const compiler::PandaGen *pg, panda::pandasm::Func
 void PatchFix::DumpFunctionInfo(const compiler::PandaGen *pg, panda::pandasm::Function *func,
     PatchFix::LiteralBuffers &literalBuffers)
 {
+    es2panda::util::Timer::timerStart(util::PATCH_FIX_COLLECT_FUNCTION_INFO, std::string(pg->Binder()->Program()->SourceFile()));
     std::stringstream ss;
 
     ss << pg->InternalName();
@@ -647,8 +650,12 @@ void PatchFix::DumpFunctionInfo(const compiler::PandaGen *pg, panda::pandasm::Fu
            << variable.second.second << SymbolTable::SECOND_LEVEL_SEPERATOR;
     }
     ss << SymbolTable::SECOND_LEVEL_SEPERATOR << std::endl;
+    es2panda::util::Timer::timerEnd(util::PATCH_FIX_COLLECT_FUNCTION_INFO, std::string(pg->Binder()->Program()->SourceFile()));
 
+
+    es2panda::util::Timer::timerStart(util::PATCH_FIX_WRITE_FUNCTION_INFO, std::string(pg->Binder()->Program()->SourceFile()));
     symbolTable_->WriteSymbolTable(ss.str());
+    es2panda::util::Timer::timerEnd(util::PATCH_FIX_WRITE_FUNCTION_INFO, std::string(pg->Binder()->Program()->SourceFile()));
 }
 
 bool PatchFix::IsAdditionalVarInPatch(uint32_t slot)
diff --git a/es2panda/util/symbolTable.cpp b/es2panda/util/symbolTable.cpp
index 2b2cbc8837..874be00cdb 100644
--- a/es2panda/util/symbolTable.cpp
+++ b/es2panda/util/symbolTable.cpp
@@ -14,6 +14,7 @@
  */
 
 #include "symbolTable.h"
+#include "timers.h"
 
 #include <fstream>
 #include <iostream>
@@ -130,14 +131,23 @@ bool SymbolTable::ReadSymbolTable(const std::string &symbolTable)
 
 void SymbolTable::WriteSymbolTable(const std::string &content)
 {
+    es2panda::util::Timer::timerStart(util::PATCH_FIX_AQUIRE_LOCK, "");
     std::lock_guard<std::mutex> lock(m_);
+    es2panda::util::Timer::timerEnd(util::PATCH_FIX_AQUIRE_LOCK, "");
+
+    es2panda::util::Timer::timerStart(util::PATCH_FIX_OPEN_FILE, "");
     std::fstream fs;
     fs.open(panda::os::file::File::GetExtendedFilePath(dumpSymbolTable_),
         std::ios_base::app | std::ios_base::in);
+
+    es2panda::util::Timer::timerEnd(util::PATCH_FIX_OPEN_FILE, "");
+
+    es2panda::util::Timer::timerStart(util::PATCH_FIX_WRITE_FILE, "");
     if (fs.is_open()) {
         fs << content;
         fs.close();
     }
+    es2panda::util::Timer::timerEnd(util::PATCH_FIX_WRITE_FILE, "");
 }
 
 std::vector<std::string_view> SymbolTable::GetStringItems(std::string_view input, const std::string &separator)
diff --git a/es2panda/util/timers.h b/es2panda/util/timers.h
index 56a9906314..dcbf5e605c 100644
--- a/es2panda/util/timers.h
+++ b/es2panda/util/timers.h
@@ -36,25 +36,40 @@ constexpr std::string_view EVENT_COMPILE_TO_PROGRAM = "Compile to program";
 constexpr std::string_view EVENT_EMIT_SINGLE_PROGRAM = "Emit single program";
 constexpr std::string_view EVENT_EMIT_MERGED_PROGRAM = "Emit merged program";
 constexpr std::string_view EVENT_EMIT_CACHE_FILE = "Emit cache file";
+constexpr std::string_view PATCH_FIX_DUMP_FUNCTION_INFO = "patch fix dump function info";
+constexpr std::string_view PATCH_FIX_COLLECT_FUNCTION_INFO = "patch fix collect function info";
+constexpr std::string_view PATCH_FIX_WRITE_FUNCTION_INFO = "patch fix write function info";
+constexpr std::string_view PATCH_FIX_AQUIRE_LOCK = "patch fix aquire lock";
+constexpr std::string_view PATCH_FIX_OPEN_FILE = "patch fix open file";
+constexpr std::string_view PATCH_FIX_WRITE_FILE = "patch fix write file";
 
 // Event level, indicating the level of an event, where each event is a sub-event of the nearest preceding level event.
 // The top-level event's level is 0
 enum EventLevel {
-    ZERO = 0,
+    ZEROTH = 0,
     FIRST,
     SECOND,
-    THIRD
+    THIRD,
+    FORTH,
+    FIFTH,
+    SIXTH
 };
 
 // Holds pairs of {event, level} according to the order during compilation process.
 // When adding new events later, please add them in the compilation order for ease of reading and maintenance.
 const std::unordered_map<std::string_view, EventLevel> eventMap = {
-    { EVENT_TOTAL, EventLevel::ZERO },
+    { EVENT_TOTAL, EventLevel::ZEROTH },
     { EVENT_COMPILE, EventLevel::FIRST },
     { EVENT_READ_INPUT_AND_CACHE, EventLevel::SECOND },
     { EVENT_COMPILE_FILE, EventLevel::SECOND },
     { EVENT_PARSE, EventLevel::THIRD },
     { EVENT_COMPILE_TO_PROGRAM, EventLevel::THIRD },
+    { PATCH_FIX_DUMP_FUNCTION_INFO, EventLevel::FORTH },
+    { PATCH_FIX_COLLECT_FUNCTION_INFO, EventLevel::FIFTH },
+    { PATCH_FIX_WRITE_FUNCTION_INFO, EventLevel::FIFTH },
+    { PATCH_FIX_AQUIRE_LOCK, EventLevel::SIXTH },
+    { PATCH_FIX_OPEN_FILE, EventLevel::SIXTH },
+    { PATCH_FIX_WRITE_FILE, EventLevel::SIXTH },
     { EVENT_OPTIMIZE_PROGRAM, EventLevel::SECOND },
     { EVENT_EMIT_ABC, EventLevel::FIRST },
     { EVENT_EMIT_SINGLE_PROGRAM, EventLevel::SECOND },
-- 
Gitee


From 7f2e954b2cc343e953e9a35d25c70dbd4746949e Mon Sep 17 00:00:00 2001
From: c00513733 <chenqiuyao@huawei.com>
Date: Thu, 20 Jun 2024 20:46:27 +0800
Subject: [PATCH 3/4] Optimize file writing and add time point in patchfix

Signed-off-by: c00513733 <chenqiuyao@huawei.com>
Change-Id: I1626257f451499a638b346bb378ff2f9a626eae2
---
 es2panda/es2panda.cpp         |  3 +++
 es2panda/util/patchFix.cpp    | 21 ++++++++++++++++++---
 es2panda/util/symbolTable.cpp | 22 +++++++++++++++++++++-
 es2panda/util/symbolTable.h   |  3 +++
 es2panda/util/timers.cpp      |  6 ++++++
 5 files changed, 51 insertions(+), 4 deletions(-)

diff --git a/es2panda/es2panda.cpp b/es2panda/es2panda.cpp
index 453276d184..6e53e34e3f 100644
--- a/es2panda/es2panda.cpp
+++ b/es2panda/es2panda.cpp
@@ -228,6 +228,9 @@ int Compiler::CompileFiles(CompilerOptions &options,
     queue = nullptr;
 
     if (symbolTable) {
+        if (!options.patchFixOptions.dumpSymbolTable.empty()) {
+            symbolTable->ActualWriteSymbolTable();
+        }
         delete symbolTable;
         symbolTable = nullptr;
     }
diff --git a/es2panda/util/patchFix.cpp b/es2panda/util/patchFix.cpp
index 5cf12225c3..a18243a998 100644
--- a/es2panda/util/patchFix.cpp
+++ b/es2panda/util/patchFix.cpp
@@ -615,12 +615,18 @@ void PatchFix::HandleFunction(const compiler::PandaGen *pg, panda::pandasm::Func
     CollectFuncDefineIns(func);
 }
 
-void PatchFix::DumpFunctionInfo(const compiler::PandaGen *pg, panda::pandasm::Function *func,
-    PatchFix::LiteralBuffers &literalBuffers)
+static double collect_function_info_time = 0.0;
+static double write_function_info_time = 0.0;
+
+void PatchFix::DumpFunctionInfo(const compiler::PandaGen *pg, [[maybe_unused]] panda::pandasm::Function *func,
+    [[maybe_unused]] PatchFix::LiteralBuffers &literalBuffers)
 {
     es2panda::util::Timer::timerStart(util::PATCH_FIX_COLLECT_FUNCTION_INFO, std::string(pg->Binder()->Program()->SourceFile()));
+
     std::stringstream ss;
 
+    auto start_time_1 = std::chrono::steady_clock::now();
+
     ss << pg->InternalName();
     ss << SymbolTable::SECOND_LEVEL_SEPERATOR << pg->InternalName() << SymbolTable::SECOND_LEVEL_SEPERATOR;
 
@@ -650,11 +656,20 @@ void PatchFix::DumpFunctionInfo(const compiler::PandaGen *pg, panda::pandasm::Fu
            << variable.second.second << SymbolTable::SECOND_LEVEL_SEPERATOR;
     }
     ss << SymbolTable::SECOND_LEVEL_SEPERATOR << std::endl;
-    es2panda::util::Timer::timerEnd(util::PATCH_FIX_COLLECT_FUNCTION_INFO, std::string(pg->Binder()->Program()->SourceFile()));
 
+    auto start_time_2 = std::chrono::steady_clock::now();
+    collect_function_info_time += std::chrono::duration_cast<std::chrono::nanoseconds>(start_time_2 - start_time_1).count();
+
+    es2panda::util::Timer::timerEnd(util::PATCH_FIX_COLLECT_FUNCTION_INFO, std::string(pg->Binder()->Program()->SourceFile()));
 
     es2panda::util::Timer::timerStart(util::PATCH_FIX_WRITE_FUNCTION_INFO, std::string(pg->Binder()->Program()->SourceFile()));
     symbolTable_->WriteSymbolTable(ss.str());
+
+    auto start_time_3 = std::chrono::steady_clock::now();
+    write_function_info_time += std::chrono::duration_cast<std::chrono::nanoseconds>(start_time_3 - start_time_2).count();
+
+    std::cout << "collect_function_info_time: "<< collect_function_info_time << "write_function_info_time: " << write_function_info_time << std::endl;
+
     es2panda::util::Timer::timerEnd(util::PATCH_FIX_WRITE_FUNCTION_INFO, std::string(pg->Binder()->Program()->SourceFile()));
 }
 
diff --git a/es2panda/util/symbolTable.cpp b/es2panda/util/symbolTable.cpp
index 874be00cdb..ab8c2ac1f5 100644
--- a/es2panda/util/symbolTable.cpp
+++ b/es2panda/util/symbolTable.cpp
@@ -135,6 +135,25 @@ void SymbolTable::WriteSymbolTable(const std::string &content)
     std::lock_guard<std::mutex> lock(m_);
     es2panda::util::Timer::timerEnd(util::PATCH_FIX_AQUIRE_LOCK, "");
 
+    // es2panda::util::Timer::timerStart(util::PATCH_FIX_OPEN_FILE, "");
+    // std::fstream fs;
+    // fs.open(panda::os::file::File::GetExtendedFilePath(dumpSymbolTable_),
+    //     std::ios_base::app | std::ios_base::in);
+
+    // es2panda::util::Timer::timerEnd(util::PATCH_FIX_OPEN_FILE, "");
+
+    // es2panda::util::Timer::timerStart(util::PATCH_FIX_WRITE_FILE, "");
+    // if (fs.is_open()) {
+    //     fs << content;
+    //     fs.close();
+    // }
+    // es2panda::util::Timer::timerEnd(util::PATCH_FIX_WRITE_FILE, "");
+
+    ss_ << content;
+}
+
+void SymbolTable::ActualWriteSymbolTable()
+{
     es2panda::util::Timer::timerStart(util::PATCH_FIX_OPEN_FILE, "");
     std::fstream fs;
     fs.open(panda::os::file::File::GetExtendedFilePath(dumpSymbolTable_),
@@ -144,12 +163,13 @@ void SymbolTable::WriteSymbolTable(const std::string &content)
 
     es2panda::util::Timer::timerStart(util::PATCH_FIX_WRITE_FILE, "");
     if (fs.is_open()) {
-        fs << content;
+        fs << ss_.str();
         fs.close();
     }
     es2panda::util::Timer::timerEnd(util::PATCH_FIX_WRITE_FILE, "");
 }
 
+
 std::vector<std::string_view> SymbolTable::GetStringItems(std::string_view input, const std::string &separator)
 {
     std::vector<std::string_view> items;
diff --git a/es2panda/util/symbolTable.h b/es2panda/util/symbolTable.h
index cb829d18d1..30d3619ab8 100644
--- a/es2panda/util/symbolTable.h
+++ b/es2panda/util/symbolTable.h
@@ -46,6 +46,7 @@ public:
 
     bool Initialize(int targetApiVersion);
     void WriteSymbolTable(const std::string &content);
+    void ActualWriteSymbolTable();
     ArenaUnorderedMap<std::string, OriginFunctionInfo> *GetOriginFunctionInfo()
     {
         return &originFunctionInfo_;
@@ -81,6 +82,8 @@ private:
     ArenaUnorderedMap<std::string, std::string> originModuleInfo_;
     // <recordName, <specialFuncIndex, specialFuncName>>
     ArenaUnorderedMap<std::string, std::unordered_map<std::string, std::string>> originRecordHashFunctionNames_;
+
+    std::stringstream ss_;
 };
 }  // namespace panda::es2panda::util
 
diff --git a/es2panda/util/timers.cpp b/es2panda/util/timers.cpp
index 4fd2c83ceb..c99dc1492b 100644
--- a/es2panda/util/timers.cpp
+++ b/es2panda/util/timers.cpp
@@ -80,9 +80,15 @@ void Timer::PrintTimers()
 
         double eventTime = 0.0;
         std::vector<std::pair<std::string, double>> eachFileTime;
+
+        // ss << "****event: " << event << std::endl;
         for (auto &[file, timePointRecord] : timeRecord.timePoints) {
             auto t = std::chrono::duration_cast<std::chrono::milliseconds>(
                 timePointRecord.endTime - timePointRecord.startTime).count();
+
+            // ss << "****file: " << file << " ,start: " <<
+            //     std::chrono::duration_cast<std::chrono::milliseconds>(timePointRecord.startTime.time_since_epoch()).count() <<
+            //     " ,end: " << std::chrono::duration_cast<std::chrono::milliseconds>(timePointRecord.endTime.time_since_epoch()).count() << std::endl;
             eventTime += t;
             if (!file.empty()) {
                 eachFileTime.push_back(std::pair(file, t));
-- 
Gitee


From 1163027c44443fc874d1f6f54aaa342b22a7eef1 Mon Sep 17 00:00:00 2001
From: c00513733 <chenqiuyao@huawei.com>
Date: Fri, 21 Jun 2024 09:32:11 +0800
Subject: [PATCH 4/4] Add patch fix timer point without optional optimization

Signed-off-by: c00513733 <chenqiuyao@huawei.com>
Change-Id: Ica6c73c9a858207c05cf0ce2813eaf7b3bc416be
---
 es2panda/es2panda.cpp         |  7 ++++---
 es2panda/util/symbolTable.cpp | 25 +++++++++++++------------
 2 files changed, 17 insertions(+), 15 deletions(-)

diff --git a/es2panda/es2panda.cpp b/es2panda/es2panda.cpp
index 6e53e34e3f..ef4c1b4703 100644
--- a/es2panda/es2panda.cpp
+++ b/es2panda/es2panda.cpp
@@ -228,9 +228,10 @@ int Compiler::CompileFiles(CompilerOptions &options,
     queue = nullptr;
 
     if (symbolTable) {
-        if (!options.patchFixOptions.dumpSymbolTable.empty()) {
-            symbolTable->ActualWriteSymbolTable();
-        }
+        // An optional optimization
+        // if (!options.patchFixOptions.dumpSymbolTable.empty()) {
+        //     symbolTable->ActualWriteSymbolTable();
+        // }
         delete symbolTable;
         symbolTable = nullptr;
     }
diff --git a/es2panda/util/symbolTable.cpp b/es2panda/util/symbolTable.cpp
index ab8c2ac1f5..9ead4482c0 100644
--- a/es2panda/util/symbolTable.cpp
+++ b/es2panda/util/symbolTable.cpp
@@ -135,21 +135,22 @@ void SymbolTable::WriteSymbolTable(const std::string &content)
     std::lock_guard<std::mutex> lock(m_);
     es2panda::util::Timer::timerEnd(util::PATCH_FIX_AQUIRE_LOCK, "");
 
-    // es2panda::util::Timer::timerStart(util::PATCH_FIX_OPEN_FILE, "");
-    // std::fstream fs;
-    // fs.open(panda::os::file::File::GetExtendedFilePath(dumpSymbolTable_),
-    //     std::ios_base::app | std::ios_base::in);
+    es2panda::util::Timer::timerStart(util::PATCH_FIX_OPEN_FILE, "");
+    std::fstream fs;
+    fs.open(panda::os::file::File::GetExtendedFilePath(dumpSymbolTable_),
+        std::ios_base::app | std::ios_base::in);
 
-    // es2panda::util::Timer::timerEnd(util::PATCH_FIX_OPEN_FILE, "");
+    es2panda::util::Timer::timerEnd(util::PATCH_FIX_OPEN_FILE, "");
 
-    // es2panda::util::Timer::timerStart(util::PATCH_FIX_WRITE_FILE, "");
-    // if (fs.is_open()) {
-    //     fs << content;
-    //     fs.close();
-    // }
-    // es2panda::util::Timer::timerEnd(util::PATCH_FIX_WRITE_FILE, "");
+    es2panda::util::Timer::timerStart(util::PATCH_FIX_WRITE_FILE, "");
+    if (fs.is_open()) {
+        fs << content;
+        fs.close();
+    }
+    es2panda::util::Timer::timerEnd(util::PATCH_FIX_WRITE_FILE, "");
 
-    ss_ << content;
+    // An optional optimization
+    // ss_ << content;
 }
 
 void SymbolTable::ActualWriteSymbolTable()
-- 
Gitee