diff --git a/ts2panda/src/base/util.ts b/ts2panda/src/base/util.ts index 4cbbb292a685ed7c64c852611580d8967af13ac1..2382bcd4d321e1b58b635e7ea7a3e629dd5518a6 100644 --- a/ts2panda/src/base/util.ts +++ b/ts2panda/src/base/util.ts @@ -229,6 +229,7 @@ export function listenErrorEvent(child: any) { child.on('error', (err: any) => { LOGD(err.toString()); + console.error(err.toString()); }); } diff --git a/ts2panda/src/compilerDriver.ts b/ts2panda/src/compilerDriver.ts index ca2e9f1f622909742de8f667ce63683fb90698c8..1205983d56ed1745e314da3d097bf6f5f3c59b20 100644 --- a/ts2panda/src/compilerDriver.ts +++ b/ts2panda/src/compilerDriver.ts @@ -53,6 +53,7 @@ import { IRNode } from "./irnodes"; import { LexicalBinder } from "./lexicalBinder"; +import { RecordTime } from "./recoredTime"; export class PendingCompilationUnit { constructor( @@ -182,9 +183,12 @@ export class CompilerDriver { } Label.resetGlobalId(); + RecordTime.recordStartTime = new Date().getTime(); let recorder = this.compilePrologue(node, true, false); let lexBinder = new LexicalBinder(node, recorder); lexBinder.resolve(); + RecordTime.recordEndTime = new Date().getTime(); + RecordTime.recordTotalCostTime += RecordTime.recordEndTime - RecordTime.recordStartTime; // initiate ts2abc if (!CmdOptions.isAssemblyMode()) { @@ -196,16 +200,20 @@ export class CompilerDriver { let ts2abcProc = this.getTs2abcProcess(); try { + RecordTime.compileTs2abcStartTime = new Date().getTime(); if (CmdOptions.isMergeAbc()) { // must keep [dumpRecord] at first Ts2Panda.dumpRecord(ts2abcProc, this.recordName); } Ts2Panda.dumpCmdOptions(ts2abcProc); + RecordTime.compileCompliationUnitStartTime = new Date().getTime(); for (let i = 0; i < this.pendingCompilationUnits.length; i++) { let unit: PendingCompilationUnit = this.pendingCompilationUnits[i]; this.compileImpl(unit.decl, unit.scope, unit.internalName, recorder); } + RecordTime.compileCompliationUnitEndTime = new Date().getTime(); + RecordTime.compileCompliationTotalCostTime += RecordTime.compileCompliationUnitEndTime - RecordTime.compileCompliationUnitStartTime; Ts2Panda.dumpStringsArray(ts2abcProc); Ts2Panda.dumpConstantPool(ts2abcProc); @@ -217,6 +225,8 @@ export class CompilerDriver { } else { terminateWritePipe(ts2abcProc); } + RecordTime.compileTs2abcEndTime = new Date().getTime(); + RecordTime.compileTs2abcTotalCostTime += RecordTime.compileTs2abcEndTime - RecordTime.compileTs2abcStartTime; if (CmdOptions.isEnableDebugLog()) { let jsonFileName = this.fileName.substring(0, this.fileName.lastIndexOf(".")).concat(".json"); diff --git a/ts2panda/src/index.ts b/ts2panda/src/index.ts index 65d1334a5575de1b0bec5216bfc668b709fc7c3e..8662b8d59008a28d5e83cba4aa7dc955fd23106b 100644 --- a/ts2panda/src/index.ts +++ b/ts2panda/src/index.ts @@ -37,6 +37,9 @@ import { terminateWritePipe, makeNameForGeneratedNode } from "./base/util"; +import { + RecordTime +} from './recoredTime' function checkIsGlobalDeclaration(sourceFile: ts.SourceFile) { for (let statement of sourceFile.statements) { @@ -65,12 +68,18 @@ function generateDTs(node: ts.SourceFile, options: ts.CompilerOptions) { } function main(fileNames: string[], options: ts.CompilerOptions, inputJsonFiles?: string[], cmdArgsSet?: Map) { + RecordTime.createProgramStartTime = new Date().getTime(); + console.error(`${RecordTime.workFileName} CreateProgram start time is: ${RecordTime.createProgramStartTime}`); const host = ts.createCompilerHost(options); if (!CmdOptions.needGenerateTmpFile()) { host.writeFile = () => {}; } let program = ts.createProgram(fileNames, options, host); + RecordTime.createProgramEndTime = new Date().getTime(); + console.error(`${RecordTime.workFileName} CreateProgram end time is: ${RecordTime.createProgramEndTime}`); + RecordTime.createProgramCostTime = RecordTime.createProgramEndTime - RecordTime.createProgramStartTime; + console.error(`${RecordTime.workFileName} CreateProgram cost time is: ${RecordTime.createProgramCostTime} ms`); let typeChecker = TypeChecker.getInstance(); typeChecker.setTypeChecker(program.getTypeChecker()); @@ -96,6 +105,7 @@ function main(fileNames: string[], options: ts.CompilerOptions, inputJsonFiles?: let initCompilerDriver = new CompilerDriver("", ""); let initTs2abcProcessState = false; + RecordTime.programEmitStartTime = new Date().getTime(); let emitResult = program.emit( undefined, undefined, @@ -107,8 +117,11 @@ function main(fileNames: string[], options: ts.CompilerOptions, inputJsonFiles?: (ctx: ts.TransformationContext) => { return (node: ts.SourceFile) => { if (CmdOptions.isCompileFilesList()) { + RecordTime.beforeStartTime = new Date().getTime(); let specifiedCmdArgs = cmdArgsSet.get(node.fileName); if (specifiedCmdArgs === undefined) { + RecordTime.beforeEndTime = new Date().getTime(); + RecordTime.beforeTotalCostTime += RecordTime.beforeEndTime - RecordTime.beforeStartTime; return node; } let originProcessArgs = process.argv.slice(0); @@ -122,6 +135,8 @@ function main(fileNames: string[], options: ts.CompilerOptions, inputJsonFiles?: let outputBinName = getOutputBinName(node); let compilerDriver = new CompilerDriver(outputBinName, getRecordName(node)); compilerDriver.compileForSyntaxCheck(node); + RecordTime.beforeEndTime = new Date().getTime(); + RecordTime.beforeTotalCostTime += RecordTime.beforeEndTime - RecordTime.beforeStartTime; return node; } } @@ -130,6 +145,7 @@ function main(fileNames: string[], options: ts.CompilerOptions, inputJsonFiles?: // @ts-ignore (ctx: ts.TransformationContext) => { return (node: ts.SourceFile) => { + RecordTime.afterStartTime = new Date().getTime(); if (CmdOptions.isCompileFilesList()) { if (!initTs2abcProcessState) { initCompilerDriver.initiateTs2abcChildProcess(["--multi-programs-pipe"]); @@ -137,9 +153,12 @@ function main(fileNames: string[], options: ts.CompilerOptions, inputJsonFiles?: } let specifiedCmdArgs = cmdArgsSet.get(node.fileName); if (specifiedCmdArgs == undefined) { + RecordTime.afterEndTime = new Date().getTime(); + RecordTime.afterTotalCostTime += RecordTime.afterEndTime - RecordTime.afterStartTime; return node; } } + RecordTime.prepareCompileStartTime = new Date().getTime(); makeNameForGeneratedNode(node); if (ts.getEmitHelpers(node)) { let newStatements = []; @@ -159,6 +178,9 @@ function main(fileNames: string[], options: ts.CompilerOptions, inputJsonFiles?: node = transformCommonjsModule(node); } let outputBinName = getOutputBinName(node); + RecordTime.prepareCompileEndTime = new Date().getTime(); + RecordTime.prepareCompileTotalCostTime += RecordTime.prepareCompileEndTime - RecordTime.prepareCompileEndTime; + RecordTime.compileAbcStartTime = new Date().getTime(); let compilerDriver = new CompilerDriver(outputBinName, getRecordName(node)); CompilerDriver.srcNode = node; setGlobalStrict(jshelpers.isEffectiveStrictModeSourceFile(node, options)); @@ -167,14 +189,22 @@ function main(fileNames: string[], options: ts.CompilerOptions, inputJsonFiles?: } else { compilerDriver.compile(node); } + RecordTime.compileAbcEndTime = new Date().getTime(); + RecordTime.compileAbcTotalCostTime += RecordTime.compileAbcEndTime - RecordTime.compileAbcStartTime; compilerDriver.showStatistics(); + RecordTime.afterEndTime = new Date().getTime(); + RecordTime.afterTotalCostTime += RecordTime.afterEndTime - RecordTime.afterStartTime; return node; } } ] } ); + RecordTime.programEmitEndTime = new Date().getTime(); + RecordTime.programEmitCostTime = RecordTime.programEmitEndTime - RecordTime.programEmitStartTime; + console.error(`${RecordTime.workFileName} Program emit cost time is: ${RecordTime.programEmitCostTime} ms`); + RecordTime.compileJsonStartTime = new Date().getTime(); if (CmdOptions.isCompileFilesList()) { if (!initTs2abcProcessState) { initCompilerDriver.initiateTs2abcChildProcess(["--multi-programs-pipe"]); @@ -190,6 +220,8 @@ function main(fileNames: string[], options: ts.CompilerOptions, inputJsonFiles?: } terminateWritePipe(initCompilerDriver.getTs2abcProcess()); } + RecordTime.compileJsonEndTime = new Date().getTime(); + RecordTime.compileJsonTotalCostTime = RecordTime.compileJsonEndTime - RecordTime.compileJsonStartTime; let allDiagnostics = ts .getPreEmitDiagnostics(program) @@ -202,10 +234,21 @@ function main(fileNames: string[], options: ts.CompilerOptions, inputJsonFiles?: } diag.printDiagnostic(diagnostic); }); + + console.error(`---${RecordTime.workFileName} Before parse cost time is: ${RecordTime.beforeTotalCostTime} ms`); + console.error(`--${RecordTime.workFileName} After parse cost time is: ${RecordTime.afterTotalCostTime} ms`); + console.error(`------${RecordTime.workFileName} Prepare compile cost time is: ${RecordTime.prepareCompileTotalCostTime} ms`); + console.error(`------${RecordTime.workFileName} Compile abc cost time is: ${RecordTime.compileAbcTotalCostTime} ms`); + console.error(`---------${RecordTime.workFileName} Record cost time is: ${RecordTime.recordTotalCostTime} ms`); + console.error(`---------${RecordTime.workFileName} Compile ts2abc cost time is: ${RecordTime.compileTs2abcTotalCostTime} ms`); + console.error(`---------${RecordTime.workFileName} Compile compliation cost time is: ${RecordTime.compileCompliationTotalCostTime} ms`); + console.error(`---------${RecordTime.workFileName} Compile pure ts2abc cost time is: ${RecordTime.compileTs2abcTotalCostTime - RecordTime.compileCompliationTotalCostTime} ms`); + console.error(`---${RecordTime.workFileName} Compile json cost time is: ${RecordTime.compileJsonTotalCostTime} ms`); } function transformSourcefilesList(parsed: ts.ParsedCommandLine | undefined) { let inputFile = CmdOptions.getCompileFilesList(); + RecordTime.workFileName = path.basename(inputFile); let sourceFileInfoArray = []; try { sourceFileInfoArray = fs.readFileSync(inputFile).toString().split("\n"); @@ -573,6 +616,8 @@ function run(args: string[], options?: ts.CompilerOptions): void { } } +RecordTime.startTime = new Date().getTime(); +console.error(`Ts2panda start time is: ${RecordTime.startTime}`); let dtsFiles = getDtsFiles(path["join"](__dirname, "../node_modules/typescript/lib")); let customLib = CmdOptions.parseCustomLibrary(process.argv); if (!customLib || customLib.length === 0) { @@ -583,3 +628,7 @@ if (!customLib || customLib.length === 0) { run(process.argv.slice(2), Compiler.Options.Default); global.gc(); +RecordTime.endTime = new Date().getTime(); +console.error(`${RecordTime.workFileName} Ts2panda end time is: ${RecordTime.endTime}`); +RecordTime.costTime = RecordTime.endTime - RecordTime.startTime; +console.error(`${RecordTime.workFileName} Ts2panda cost time is: ${RecordTime.costTime} ms`); \ No newline at end of file diff --git a/ts2panda/src/recoredTime.ts b/ts2panda/src/recoredTime.ts new file mode 100644 index 0000000000000000000000000000000000000000..9bccf2656b1404a52d0a256ce84284abf9acaab8 --- /dev/null +++ b/ts2panda/src/recoredTime.ts @@ -0,0 +1,60 @@ +export class RecordTime { + static workFileName: string; + + // costTime = createProgramCostTime + programEmitCostTime; + static startTime: number; + static endTime: number; + static costTime: number; + + // cost time by calling create program of tsc + static createProgramStartTime: number; + static createProgramEndTime: number; + static createProgramCostTime: number; + + // cost time by calling program emit of tsc + // programEmitCostTime = tsc + beforeTotalTime + afterTotalTime + static programEmitStartTime: number; + static programEmitEndTime: number; + static programEmitCostTime: number; + + // cost time by calling program emit before parse of tsc, checkSyntax of ts2panda + static beforeStartTime: number; + static beforeEndTime: number; + static beforeTotalCostTime: number = 0; + + // cost time by calling program emit after parse of tsc + // afterTotalCostTime = prepareCompileTotalCostTime + compileAbcTotalCostTime + static afterStartTime: number; + static afterEndTime: number; + static afterTotalCostTime: number = 0; + + static prepareCompileStartTime: number; + static prepareCompileEndTime: number; + static prepareCompileTotalCostTime: number = 0; + + // cost time by calling gen abc + // compileAbcTotalCostTime = recordTotalCostTime + compileTs2abcTotalCostTime + static compileAbcStartTime: number; + static compileAbcEndTime: number; + static compileAbcTotalCostTime: number = 0; + + // record identifer of ast + static recordStartTime: number; + static recordEndTime: number; + static recordTotalCostTime: number = 0; + + // gen bytecode of abc + static compileCompliationUnitStartTime: number; + static compileCompliationUnitEndTime: number; + static compileCompliationTotalCostTime: number = 0; + + // ts2abc process to gen abc file + static compileTs2abcStartTime: number; + static compileTs2abcEndTime: number; + static compileTs2abcTotalCostTime: number = 0; + + // compile json file to abc file + static compileJsonStartTime: number; + static compileJsonEndTime: number; + static compileJsonTotalCostTime: number = 0; +} \ No newline at end of file diff --git a/ts2panda/ts2abc/main.cpp b/ts2panda/ts2abc/main.cpp index d5d2230339251c19906522cf890a1271df924ed1..eed447dbf37a53f67592e959bc05abcf1d2fbbaa 100644 --- a/ts2panda/ts2abc/main.cpp +++ b/ts2panda/ts2abc/main.cpp @@ -12,6 +12,7 @@ * See the License for the specific language governing permissions and * limitations under the License. */ +#include #include "assembly-type.h" #include "assembly-program.h" @@ -20,6 +21,8 @@ #include "ts2abc_options.h" #include "ts2abc.h" +uint32_t js2abcCostTime = 0U; + int Preprocess(const panda::ts2abc::Options &options, const panda::PandArgParser &argParser, std::string &output, std::string &data, const std::string &usage) { @@ -75,6 +78,7 @@ bool HandleNpmEntries(const panda::ts2abc::Options &options, const panda::PandAr int main(int argc, const char *argv[]) { + auto startTime = std::chrono::steady_clock::now(); panda::PandArgParser argParser; panda::Span sp(argv, argc); panda::ts2abc::Options options(sp[0]); @@ -123,6 +127,9 @@ int main(int argc, const char *argv[]) std::cerr << "call GenerateProgramsFromPipe fail" << std::endl; return panda::ts2abc::RETURN_FAILED; } + auto multiEndTime = std::chrono::steady_clock::now(); + js2abcCostTime += std::chrono::duration_cast(multiEndTime - startTime).count(); + std::cerr << "js2abc cost time is: " << js2abcCostTime << " ms" << std::endl; return panda::ts2abc::RETURN_SUCCESS; } @@ -138,5 +145,8 @@ int main(int argc, const char *argv[]) return panda::ts2abc::RETURN_FAILED; } + auto endTime = std::chrono::steady_clock::now(); + js2abcCostTime += std::chrono::duration_cast(endTime - startTime).count(); + std::cerr << "---js2abc cost time is: " << js2abcCostTime << " ms" << std::endl; return panda::ts2abc::RETURN_SUCCESS; } diff --git a/ts2panda/ts2abc/ts2abc.cpp b/ts2panda/ts2abc/ts2abc.cpp index 777118eee3a4f922415e5180fc8c5161ccee0055..eb0f256ffb1e84bdcdd212cfe45e4186207c4263 100644 --- a/ts2panda/ts2abc/ts2abc.cpp +++ b/ts2panda/ts2abc/ts2abc.cpp @@ -19,6 +19,7 @@ #include #include #include +#include #include "assembly-type.h" #include "assembly-program.h" @@ -57,6 +58,10 @@ constexpr uint32_t LITERALBUFFERINDEXOFFSET = 100; uint32_t MAX_UINT8 = static_cast(std::numeric_limits::max()); bool g_isOutputProto = false; static constexpr const char* PROTO_BIN_SUFFIX = "protoBin"; +uint32_t g_emitProgramCostTime = 0U; +uint32_t g_parseJsonCostTime = 0U; +uint32_t g_handleBufferCostTime = 0U; +uint32_t g_readFromPipeCostTime = 0U; constexpr std::size_t BOUND_LEFT = 0; constexpr std::size_t BOUND_RIGHT = 0; @@ -1306,6 +1311,7 @@ static void ParseSingleTypeInfo(const Json::Value &rootValue, panda::pandasm::Pr static int ParseSmallPieceJson(const std::string &subJson, panda::pandasm::Program &prog) { + auto parseJsonStartTime = std::chrono::steady_clock::now(); Json::Value rootValue; if (ParseJson(subJson, rootValue)) { std::cerr <<" Fail to parse json by JsonCPP" << std::endl; @@ -1383,6 +1389,8 @@ static int ParseSmallPieceJson(const std::string &subJson, panda::pandasm::Progr return RETURN_FAILED; } } + auto parseJsonEndTime = std::chrono::steady_clock::now(); + g_parseJsonCostTime += std::chrono::duration_cast(parseJsonEndTime - parseJsonStartTime).count(); return RETURN_SUCCESS; } @@ -1493,6 +1501,7 @@ static bool EmitProgram(const std::string &output, int optLevel, std::string opt static bool EmitAndRestoreProgram(panda::pandasm::Program &prog, const panda::ts2abc::Options &options) { + auto startEmitProgramTime = std::chrono::steady_clock::now(); if (!EmitProgram(g_outputFileName, options.GetOptLevelArg(), options.GetOptLogLevelArg(), prog)) { std::cerr << "fail to emit porgram " << g_outputFileName << " in HandleBuffer" << std::endl; return false; @@ -1500,12 +1509,15 @@ static bool EmitAndRestoreProgram(panda::pandasm::Program &prog, const panda::ts prog = panda::pandasm::Program(); prog.lang = panda::pandasm::extensions::Language::ECMASCRIPT; g_newLiteralArrayIndex = -1; + auto endEmitProgramTime = std::chrono::steady_clock::now(); + g_emitProgramCostTime += std::chrono::duration_cast(endEmitProgramTime - startEmitProgramTime).count(); return true; } static bool HandleBuffer(const int &ret, char *buff, std::string &data, panda::pandasm::Program &prog, const panda::ts2abc::Options &options) { + auto handleBufferStartTime = std::chrono::steady_clock::now(); uint32_t startPos = 0; if (options.IsMultiProgramsPipe() && ((buff[0] == '*' && data.back() != '#') || (buff[0] == '\n' && buff[1] == '*'))) { @@ -1548,11 +1560,14 @@ static bool HandleBuffer(const int &ret, char *buff, std::string &data, panda::p data += substr; } + auto handleBufferEndTime = std::chrono::steady_clock::now(); + g_handleBufferCostTime += std::chrono::duration_cast(handleBufferEndTime - handleBufferStartTime).count(); return true; } static bool ReadFromPipe(panda::pandasm::Program &prog, panda::ts2abc::Options options) { + auto readFromPipeStartime = std::chrono::steady_clock::now(); std::string data; const size_t bufSize = 4096; // the parent process open a pipe to this child process with fd of 3 @@ -1575,11 +1590,14 @@ static bool ReadFromPipe(panda::pandasm::Program &prog, panda::ts2abc::Options o } Logd("finish parsing from pipe"); + auto readFromPipeEndime = std::chrono::steady_clock::now(); + g_readFromPipeCostTime += std::chrono::duration_cast(readFromPipeEndime - readFromPipeStartime).count(); return true; } bool GenerateProgramsFromPipe(const panda::ts2abc::Options &options) { + auto generateProgramsFromPipeStartTime = std::chrono::steady_clock::now(); panda::pandasm::Program prog = panda::pandasm::Program(); prog.lang = panda::pandasm::extensions::Language::ECMASCRIPT; @@ -1588,6 +1606,13 @@ bool GenerateProgramsFromPipe(const panda::ts2abc::Options &options) return false; } + auto generateProgramsFromPipeEndTime = std::chrono::steady_clock::now(); + auto generateProgramsFromPipeCostTime = std::chrono::duration_cast(generateProgramsFromPipeEndTime - generateProgramsFromPipeStartTime).count(); + std::cerr << "------js2abc generate programs from pipe cost time is: " << generateProgramsFromPipeCostTime << " ms" << std::endl; + std::cerr << "---------js2abc read from pipe cost time is: " << g_readFromPipeCostTime << " ms" << std::endl; + std::cerr << "------------js2abc handle buffer cost time is: " << g_handleBufferCostTime << " ms" << std::endl; + std::cerr << "---------------js2abc parse json cost time is: " << g_parseJsonCostTime << " ms" << std::endl; + std::cerr << "---------------js2abc emit program cost time is: " << g_emitProgramCostTime << " ms" << std::endl; return true; }