Merge pull request #3517 from xmake-io/profile

Profile compile and link

11 files changed, 221 insertions, 46 deletions

diff --git a/xmake/core/base/profiler.lua b/xmake/core/base/profiler.lua
index 429715eae..09b4c45f5 100644
--- a/xmake/core/base/profiler.lua
+++ b/xmake/core/base/profiler.lua
@@ -24,6 +24,7 @@ local profiler = {}
 -- load modules
 local os        = require("base/os")
 local path      = require("base/path")
+local heap      = require("base/heap")
 local table     = require("base/table")
 local utils     = require("base/utils")
 local string    = require("base/string")
@@ -52,11 +53,10 @@ function profiler:_func_report(funcinfo)
     local key = self:_func_key(funcinfo)
     local report = self._REPORTS_BY_KEY[key]
     if not report then
-        report =
-        {
-            funcinfo    = funcinfo
-        ,   callcount   = 0
-        ,   totaltime   = 0
+        report = {
+            funcinfo    = funcinfo,
+            callcount   = 0,
+            totaltime   = 0
         }
         self._REPORTS_BY_KEY[key] = report
         table.insert(self._REPORTS, report)
@@ -64,6 +64,55 @@ function profiler:_func_report(funcinfo)
     return report
 end
 
+-- get the tag key
+function profiler:_tag_key(name, argv)
+    local key = name
+    if argv then
+        for _, item in ipairs(argv) do
+            if type(item) == "table" then
+                key = key .. os.args(item)
+            else
+                key = key .. tostring(item)
+            end
+        end
+    end
+    return key
+end
+
+-- get the tag title
+function profiler:_tag_title(name, argv)
+    local key = name
+    if argv then
+        for _, item in ipairs(argv) do
+            if type(item) == "table" then
+                key = key .. ": " .. os.args(item)
+            else
+                key = key .. ": " .. tostring(item)
+            end
+        end
+    end
+    return key
+end
+
+-- get the tag report
+function profiler:_tag_report(name, argv)
+    self._REPORTS_BY_KEY = self._REPORTS_BY_KEY or {}
+    local key = self:_tag_key(name, argv)
+    local report = self._REPORTS_BY_KEY[key]
+    if not report then
+        report = {
+            name        = name,
+            argv        = argv,
+            callcount   = 0,
+            totaltime   = 0
+        }
+        self._REPORTS_BY_KEY[key] = report
+        self._REPORTS = self._REPORTS or {}
+        table.insert(self._REPORTS, report)
+    end
+    return report
+end
+
 -- profiling call
 function profiler:_profiling_call(funcinfo)
     local report = self:_func_report(funcinfo)
@@ -106,10 +155,9 @@ end
 
 -- start profiling
 function profiler:start()
-    local mode = self:mode()
-    if mode and mode == "trace" then
+    if self:is_trace() then
         debug.sethook(profiler._tracing_handler, 'cr', 0)
-    else
+    elseif self:is_perf("call") then
         self._REPORTS        = self._REPORTS or {}
         self._REPORTS_BY_KEY = self._REPORTS_BY_KEY or {}
         self._STARTIME       = self._STARTIME or os.clock()
@@ -119,44 +167,87 @@ end
 
 -- stop profiling
 function profiler:stop()
-
-    -- trace?
-    local mode = self:mode()
-    if mode and mode == "trace" then
-        -- stop to hook
+    if self:is_trace() then
         debug.sethook()
-    else
-
-        -- save the stop time
+    elseif self:is_perf("call") then
         self._STOPTIME = os.clock()
-
-        -- stop to hook
         debug.sethook()
 
         -- calculate the total time
         local totaltime = self._STOPTIME - self._STARTIME
 
         -- sort reports
-        table.sort(self._REPORTS, function(a, b)
+        local reports = self._REPORTS or {}
+        table.sort(reports, function(a, b)
             return a.totaltime > b.totaltime
         end)
 
         -- show reports
-        for _, report in ipairs(self._REPORTS) do
-
-            -- calculate percent
+        for _, report in ipairs(reports) do
             local percent = (report.totaltime / totaltime) * 100
             if percent < 1 then
                 break
             end
-
-            -- trace
             utils.print("%6.3f, %6.2f%%, %7d, %s", report.totaltime, percent, report.callcount, self:_func_title(report.funcinfo))
         end
+    elseif self:is_perf("tag") then
+
+        -- sort reports, topN
+        local reports = self._REPORTS or {}
+        local h = heap.valueheap({cmp = function(a, b)
+            return a.totaltime > b.totaltime
+        end})
+        for _, report in ipairs(reports) do
+            h:push(report)
+        end
+
+        -- show reports
+        local count = 0
+        while count < 64 and h:length() > 0 do
+            local report = h:pop()
+            utils.print("%6.3f, %7d, %s", report.totaltime, report.callcount, self:_tag_title(report.name, report.argv))
+            count = count + 1
+        end
+        if h:length() > 0 then
+            utils.print("...")
+        end
    end
 end
 
--- get profiler mode, e.g. perf, trace
+-- enter the given tag for perl:tag
+function profiler:enter(name, ...)
+    local is_perf_tag = self._IS_PERF_TAG
+    if is_perf_tag == nil then
+        is_perf_tag = self:is_perf("tag")
+        self._IS_PERF_TAG = is_perf_tag
+    end
+    if is_perf_tag then
+        local argv = table.pack(...)
+        local report = self:_tag_report(name, argv)
+        report.calltime    = os.clock()
+        report.callcount   = report.callcount + 1
+    end
+end
+
+-- leave the given tag for perl:tag
+function profiler:leave(name, ...)
+    local is_perf_tag = self._IS_PERF_TAG
+    if is_perf_tag == nil then
+        is_perf_tag = self:is_perf("tag")
+        self._IS_PERF_TAG = is_perf_tag
+    end
+    if is_perf_tag then
+        local stoptime = os.clock()
+        local argv = table.pack(...)
+        local report = self:_tag_report(name, argv)
+        if report.calltime and report.calltime > 0 then
+            report.totaltime = report.totaltime + (stoptime - report.calltime)
+            report.calltime = 0
+        end
+    end
+end
+
+-- get profiler mode, e.g. perf:call, perf:tag, trace
 function profiler:mode()
     local mode = self._MODE
     if mode == nil then
@@ -166,10 +257,23 @@ function profiler:mode()
     return mode or nil
 end
 
+-- is trace?
+function profiler:is_trace()
+    local mode = self:mode()
+    return mode and mode == "trace"
+end
+
+-- is perf?
+function profiler:is_perf(name)
+    local mode = self:mode()
+    if mode and name then
+        return mode == "perf:" .. name
+    end
+end
+
 -- profiler is enabled?
 function profiler:enabled()
-    local mode = self:mode()
-    return mode ~= nil and (mode == "trace" or mode == "perf")
+    return self:is_perf("call") or self:is_perf("tag") or self:is_trace()
 end
 
 -- return module
diff --git a/xmake/core/package/package.lua b/xmake/core/package/package.lua
index f279950d0..a7171c1d1 100644
--- a/xmake/core/package/package.lua
+++ b/xmake/core/package/package.lua
@@ -1507,12 +1507,10 @@ function _instance:_fetch_tool(opt)
                 end
             end
         else
-            print("find_tool", self:name())
             fetchinfo = self:find_tool(self:name(), {require_version = opt.require_version,
                                                      cachekey = "fetch_package_xmake",
                                                      norun = true, -- we need not run it to check for xmake/packages, @see https://github.com/xmake-io/xmake-repo/issues/66
                                                      force = opt.force})
-            print("fetchinfo", fetchinfo)
 
             -- may be toolset, not single tool
             if not fetchinfo then
diff --git a/xmake/core/sandbox/modules/import/core/base/profiler.lua b/xmake/core/sandbox/modules/import/core/base/profiler.lua
new file mode 100644
index 000000000..cd2a42460
--- /dev/null
+++ b/xmake/core/sandbox/modules/import/core/base/profiler.lua
@@ -0,0 +1,40 @@
+--!A cross-platform build utility based on Lua
+--
+-- 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.
+--
+-- Copyright (C) 2015-present, TBOOX Open Source Group.
+--
+-- @author      ruki
+-- @file        profiler.lua
+--
+
+-- define module
+local sandbox_core_base_profiler = sandbox_core_base_profiler or {}
+
+-- load modules
+local profiler = require("base/profiler")
+local raise    = require("sandbox/modules/raise")
+
+-- enter tag
+function sandbox_core_base_profiler.enter(name, ...)
+    profiler:enter(name, ...)
+end
+
+-- leave tag
+function sandbox_core_base_profiler.leave(name, ...)
+    profiler:leave(name, ...)
+end
+
+-- return module
+return sandbox_core_base_profiler
+
diff --git a/xmake/core/sandbox/modules/import/lib/detect/find_file.lua b/xmake/core/sandbox/modules/import/lib/detect/find_file.lua
index 0c878e87d..9d7448ea8 100644
--- a/xmake/core/sandbox/modules/import/lib/detect/find_file.lua
+++ b/xmake/core/sandbox/modules/import/lib/detect/find_file.lua
@@ -26,6 +26,7 @@ local os        = require("base/os")
 local path      = require("base/path")
 local utils     = require("base/utils")
 local table     = require("base/table")
+local profiler  = require("base/profiler")
 local raise     = require("sandbox/modules/raise")
 local vformat   = require("sandbox/modules/vformat")
 
@@ -70,16 +71,18 @@ function sandbox_lib_detect_find_file.main(name, paths, opt)
     opt = opt or {}
 
     -- find file
+    profiler:enter("find_file", name)
+    local results
     local suffixes = table.wrap(opt.suffixes)
     for _, _path in ipairs(table.wrap(paths)) do
 
         -- format path for builtin variables
         if type(_path) == "function" then
-            local ok, results = sandbox.load(_path)
+            local ok, result_or_errors = sandbox.load(_path)
             if ok then
-                _path = results or ""
+                _path = result_or_errors or ""
             else
-                raise(results)
+                raise(result_or_errors)
             end
         elseif type(_path) == "string" then
             if _path:match("^%$%(env .+%)$") then
@@ -95,21 +98,24 @@ function sandbox_lib_detect_find_file.main(name, paths, opt)
                 if #suffixes > 0 then
                     for _, suffix in ipairs(suffixes) do
                         local filedir = path.join(_s_path, suffix)
-                        local results = sandbox_lib_detect_find_file._find(filedir, name)
+                        results = sandbox_lib_detect_find_file._find(filedir, name)
                         if results then
-                            return results
+                            goto found
                         end
                     end
                 else
                     -- find file in the given path
-                    local results = sandbox_lib_detect_find_file._find(_s_path, name)
+                    results = sandbox_lib_detect_find_file._find(_s_path, name)
                     if results then
-                        return results
+                        goto found
                     end
                 end
             end
         end
     end
+::found::
+    profiler:leave("find_file", name)
+    return results
 end
 
 -- return module
diff --git a/xmake/core/sandbox/modules/import/lib/detect/find_path.lua b/xmake/core/sandbox/modules/import/lib/detect/find_path.lua
index a88562a76..78b9f4c9d 100644
--- a/xmake/core/sandbox/modules/import/lib/detect/find_path.lua
+++ b/xmake/core/sandbox/modules/import/lib/detect/find_path.lua
@@ -25,6 +25,7 @@ local sandbox_lib_detect_find_path = sandbox_lib_detect_find_path or {}
 local os        = require("base/os")
 local path      = require("base/path")
 local table     = require("base/table")
+local profiler  = require("base/profiler")
 local raise     = require("sandbox/modules/raise")
 local vformat   = require("sandbox/modules/vformat")
 
@@ -76,16 +77,18 @@ function sandbox_lib_detect_find_path.main(name, paths, opt)
     opt = opt or {}
 
     -- find path
+    local results
+    profiler:enter("find_path", name)
     local suffixes = table.wrap(opt.suffixes)
     for _, _path in ipairs(table.wrap(paths)) do
 
         -- format path for builtin variables
         if type(_path) == "function" then
-            local ok, results = sandbox.load(_path)
+            local ok, result_or_errors = sandbox.load(_path)
             if ok then
-                _path = results or ""
+                _path = result_or_errors or ""
             else
-                raise(results)
+                raise(result_or_errors)
             end
         else
             _path = vformat(_path)
@@ -95,19 +98,22 @@ function sandbox_lib_detect_find_path.main(name, paths, opt)
         if #suffixes > 0 then
             for _, suffix in ipairs(suffixes) do
                 local filedir = path.join(_path, suffix)
-                local results = sandbox_lib_detect_find_path._find(filedir, name)
+                results = sandbox_lib_detect_find_path._find(filedir, name)
                 if results then
-                    return results
+                    goto found
                 end
             end
         else
             -- find file in the given path
-            local results = sandbox_lib_detect_find_path._find(_path, name)
+            results = sandbox_lib_detect_find_path._find(_path, name)
             if results then
-                return results
+                goto found
             end
         end
     end
+::found::
+    profiler:leave("find_path", name)
+    return results
 end
 
 -- return module
diff --git a/xmake/core/sandbox/modules/import/lib/detect/find_program.lua b/xmake/core/sandbox/modules/import/lib/detect/find_program.lua
index 2bb04697e..2ac26e660 100644
--- a/xmake/core/sandbox/modules/import/lib/detect/find_program.lua
+++ b/xmake/core/sandbox/modules/import/lib/detect/find_program.lua
@@ -28,6 +28,7 @@ local option      = require("base/winos")
 local table       = require("base/table")
 local utils       = require("base/utils")
 local option      = require("base/option")
+local profiler    = require("base/profiler")
 local project     = require("project/project")
 local detectcache = require("cache/detectcache")
 local sandbox     = require("sandbox/sandbox")
@@ -303,7 +304,9 @@ function sandbox_lib_detect_find_program.main(name, opt)
 
     -- find executable program
     checking = coroutine_running and name or nil
+    profiler:enter("find_program", name)
     result = sandbox_lib_detect_find_program._find(name, paths, opt)
+    profiler:leave("find_program", name)
     checking = nil
 
     -- cache result
diff --git a/xmake/core/sandbox/modules/import/lib/detect/find_programver.lua b/xmake/core/sandbox/modules/import/lib/detect/find_programver.lua
index 376b11005..988180ecb 100644
--- a/xmake/core/sandbox/modules/import/lib/detect/find_programver.lua
+++ b/xmake/core/sandbox/modules/import/lib/detect/find_programver.lua
@@ -28,6 +28,7 @@ local table       = require("base/table")
 local utils       = require("base/utils")
 local option      = require("base/option")
 local semver      = require("base/semver")
+local profiler    = require("base/profiler")
 local project     = require("project/project")
 local detectcache = require("cache/detectcache")
 local sandbox     = require("sandbox/sandbox")
@@ -81,6 +82,7 @@ function sandbox_lib_detect_find_programver.main(program, opt)
 
     -- attempt to get version output info
     checking = coroutine_running and program or nil
+    profiler:enter("find_programver", program)
     local ok = false
     local outdata = nil
     local command = opt.command
@@ -95,6 +97,7 @@ function sandbox_lib_detect_find_programver.main(program, opt)
         ok, outdata = os.iorunv(program, {command or "--version"}, {envs = opt.envs})
     end
     checking = nil
+    profiler:leave("find_programver", program)
 
     -- find version info
     if ok and outdata and #outdata > 0 then
diff --git a/xmake/core/tool/compiler.lua b/xmake/core/tool/compiler.lua
index bf5dead36..8dc7bffd9 100644
--- a/xmake/core/tool/compiler.lua
+++ b/xmake/core/tool/compiler.lua
@@ -28,6 +28,7 @@ local utils     = require("base/utils")
 local table     = require("base/table")
 local string    = require("base/string")
 local option    = require("base/option")
+local profiler  = require("base/profiler")
 local tool      = require("tool/tool")
 local builder   = require("tool/builder")
 local config    = require("project/config")
@@ -269,7 +270,10 @@ function compiler:compile(sourcefiles, objectfile, opt)
     -- compile it
     opt = table.copy(opt)
     opt.target = self:target()
-    return sandbox.load(self:_tool().compile, self:_tool(), sourcefiles, objectfile, opt.dependinfo, compflags, opt)
+    profiler:enter(self:name(), "compile", sourcefiles)
+    local ok, errors = sandbox.load(self:_tool().compile, self:_tool(), sourcefiles, objectfile, opt.dependinfo, compflags, opt)
+    profiler:leave(self:name(), "compile", sourcefiles)
+    return ok, errors
 end
 
 -- get the compile arguments list
diff --git a/xmake/core/tool/linker.lua b/xmake/core/tool/linker.lua
index 09436aeee..88b6da6a9 100644
--- a/xmake/core/tool/linker.lua
+++ b/xmake/core/tool/linker.lua
@@ -28,6 +28,7 @@ local utils     = require("base/utils")
 local table     = require("base/table")
 local string    = require("base/string")
 local option    = require("base/option")
+local profiler  = require("base/profiler")
 local config    = require("project/config")
 local sandbox   = require("sandbox/sandbox")
 local language  = require("language/language")
@@ -217,7 +218,10 @@ function linker:link(objectfiles, targetfile, opt)
     local linkflags = opt.linkflags or self:linkflags(opt)
     opt = table.copy(opt)
     opt.target = self:target()
-    return sandbox.load(self:_tool().link, self:_tool(), table.wrap(objectfiles), self:_targetkind(), targetfile, linkflags, opt)
+    profiler:enter(self:name(), "link", targetfile)
+    local ok, errors = sandbox.load(self:_tool().link, self:_tool(), table.wrap(objectfiles), self:_targetkind(), targetfile, linkflags, opt)
+    profiler:leave(self:name(), "link", targetfile)
+    return ok, errors
 end
 
 -- get the link arguments list
diff --git a/xmake/modules/lib/detect/has_flags.lua b/xmake/modules/lib/detect/has_flags.lua
index 3567ceae6..dc11db11c 100644
--- a/xmake/modules/lib/detect/has_flags.lua
+++ b/xmake/modules/lib/detect/has_flags.lua
@@ -21,6 +21,7 @@
 -- imports
 import("core.base.option")
 import("core.base.scheduler")
+import("core.base.profiler")
 import("core.project.config")
 import("core.cache.detectcache")
 import("lib.detect.find_tool")
@@ -117,6 +118,9 @@ function main(name, flags, opt)
     end
     checkflags = results
 
+    -- start profile
+    profiler.enter("has_flags", tool.name, checkflags[1])
+
     -- detect.tools.xxx.has_flags(flags, opt)?
     _g._checking = coroutine_running and key or nil
     local hasflags = import("detect.tools." .. tool.name .. ".has_flags", {try = true})
@@ -132,6 +136,9 @@ function main(name, flags, opt)
     _g._checking = nil
     result = result or false
 
+    -- stop profile
+    profiler.leave("has_flags", tool.name, checkflags[1])
+
     -- trace
     if option.get("verbose") or option.get("diagnosis") or opt.verbose then
         cprintf("${dim}checking for flags (")
diff --git a/xmake/plugins/show/lists/envs.lua b/xmake/plugins/show/lists/envs.lua
index 753efd997..11d3ffc59 100644
--- a/xmake/plugins/show/lists/envs.lua
+++ b/xmake/plugins/show/lists/envs.lua
@@ -36,7 +36,7 @@ function main()
                     XMAKE_RAMDIR         = {"Set the ramdisk directory.", os.getenv("XMAKE_RAMDIR")},
                     XMAKE_RCFILES        = {"Set the runtime configuration files.", path.joinenv(project.rcfiles())},
                     XMAKE_TMPDIR         = {"Set the temporary directory.", os.tmpdir()},
-                    XMAKE_PROFILE        = {"Start profiler, e.g. perf, trace, stuck.", os.getenv("XMAKE_PROFILE")},
+                    XMAKE_PROFILE        = {"Start profiler, e.g. perf:call, perf:tag, trace, stuck.", os.getenv("XMAKE_PROFILE")},
                     XMAKE_PKG_CACHEDIR   = {"Set the cache directory of packages.", os.getenv("XMAKE_PKG_CACHEDIR")},
                     XMAKE_PKG_INSTALLDIR = {"Set the install directory of packages.", os.getenv("XMAKE_PKG_INSTALLDIR")}}
     local width = 24