vk: VRAM, system RAM, GPU and replay CPU time: streams and staging out of VRAM, memory given back when idle, redundant barriers left out, draw setup cached

gpu/vk/vk_coopmat.cpp

@@ -18,6 +18,7 @@
 #include "vk_internal.h"
 #include "shader_recompiler/backend/spirv/mma_layout.h"
 #include <sirit/sirit.h>
+#include "vk_work.h"   // (after the others: counts the commands that do GPU work, for full_barrier)
 
 namespace mkwvk {
 namespace {

gpu/vk/vk_dump.cpp

@@ -11,6 +11,7 @@
 #include <direct.h>
 
 #include "vk_dump.h"
+#include "vk_work.h"   // (after the others: counts the commands that do GPU work, for full_barrier)
 
 namespace mkwvk {
 namespace {

gpu/vk/vk_framegen.cpp

@@ -26,6 +26,7 @@
 #include "shaders/fg_median_comp_spv.h"
 #include "shaders/fg_scale_comp_spv.h"
 #include "shaders/fg_synth_comp_spv.h"
+#include "vk_work.h"   // (after the others: counts the commands that do GPU work, for full_barrier)
 
 namespace mkwvk {
 extern std::atomic<uint32_t> present_kind;   // (vk_replay.cpp: the frame log's)

gpu/vk/vk_gprof.cpp

@@ -1,7 +1,8 @@
-// GPU profile (vk_gprof.h): a query pool of timestamp pairs per recording slot.
+// GPU profile (vk_gprof.h): a query pool of timestamps per recording slot and command buffer (the recording's, and its upload one).
 #include <algorithm>
 #include <cstdio>
 #include <cstdlib>
+#include <map>
 #include <unordered_map>
 #include <vector>
 
@@ -11,89 +12,241 @@ namespace mkwvk {
 namespace {
 
 constexpr int kSlots = 48;                // (vk_replay.cpp's kRecordings)
-constexpr uint32_t kPairs = 1024;         // spans a recording can time
+constexpr uint32_t kQ = 2048;             // timestamps a command buffer can take in a recording
 VkQueryPool pool = VK_NULL_HANDLE;
+struct Span {
+    std::string label;
+    uint32_t qb = 0, qe = 0;              // (its timestamps: a run of a pass shares them with its neighbours)
+    int items = 1;
+    uint64_t bytes = 0;
+    bool nested = false;                  // (a program's run inside a pass: counted by itself, not in the command buffer's total)
+};
+struct Stream {
+    VkCommandBuffer cmd = VK_NULL_HANDLE;
+    uint32_t base = 0;                    // (its first query)
+    std::vector<Span> spans;
+    uint32_t nq = 0;                      // (timestamps taken)
+    uint32_t dirty = kQ;                  // (queries that may hold a result: the next use resets them; all of them before the first)
+    int outer = -1;                       // (the open span)
+    int run = -1;                         // (the open program run of the open pass, RX_VK_PASS_TIMING=2)
+    uint64_t run_key = 0;
+};
 struct Slot {
-    std::vector<std::string> labels;      // one a closed span
-    bool open = false;
-    bool used = false;
+    Stream s[2];                          // (0: the recording's command buffer, 1: its upload command buffer)
+    bool used = false, up_sent = false;
 };
 Slot slots[kSlots];
 int cur = -1;
-std::unordered_map<std::string, std::pair<double, int64_t>> totals;   // label -> (ns, spans)
+struct Agg {
+    double ns = 0;
+    int64_t n = 0, items = 0;
+    uint64_t bytes = 0;
+};
+std::unordered_map<std::string, Agg> totals[2];   // label -> what its spans took, per command buffer kind
+double active_ns[2], sum_ns[2];                   // (the command buffers' first timestamp to last, and what their spans took)
+int64_t recs[2], dropped;
+int acc_frames = 0;
+
+Stream* find(VkCommandBuffer cmd) {
+    if (!pool || cur < 0 || !cmd) return nullptr;
+    for (Stream& s : slots[cur].s)
+        if (s.cmd == cmd) return &s;
+    return nullptr;
+}
+uint32_t stamp(Stream& st, VkCommandBuffer cmd) {
+    vkCmdWriteTimestamp2(cmd, VK_PIPELINE_STAGE_2_ALL_COMMANDS_BIT, pool, st.base + st.nq);
+    return st.nq++;
+}
 
 } // namespace
 
 bool gprof_on() {
-    static const bool on = getenv("RX_VK_GPU_PROFILE") && atoi(getenv("RX_VK_GPU_PROFILE")) != 0;
+    static const bool on = [] {
+        const char* a = getenv("RX_VK_PASS_TIMING");
+        const char* b = getenv("RX_VK_GPU_PROFILE");
+        return (a && atoi(a) != 0) || (b && atoi(b) != 0);
+    }();
     return on;
 }
+static int level() {
+    static const int v = [] {
+        const char* a = getenv("RX_VK_PASS_TIMING");
+        return a ? atoi(a) : 1;
+    }();
+    return v;
+}
 
-void gprof_begin_recording(int slot, VkCommandBuffer cmd) {
+void gprof_begin_recording(int slot, VkCommandBuffer cmd, VkCommandBuffer upload) {
     if (!gprof_on() || slot < 0 || slot >= kSlots) return;
     if (!pool) {
         VkQueryPoolCreateInfo qi{VK_STRUCTURE_TYPE_QUERY_POOL_CREATE_INFO};
         qi.queryType = VK_QUERY_TYPE_TIMESTAMP;
-        qi.queryCount = kSlots * kPairs * 2;
+        qi.queryCount = kSlots * 2 * kQ;
         if (vkCreateQueryPool(dev.device, &qi, nullptr, &pool) != VK_SUCCESS) return;
-        logf("vk: GPU profile on (RX_VK_GPU_PROFILE)");
+        logf("vk: GPU pass timing on (RX_VK_PASS_TIMING=%d): every 600 presents the spans of GPU work are logged", level());
     }
     cur = slot;
     Slot& s = slots[slot];
-    s.labels.clear();
-    s.open = false;
-    s.used = true;
-    vkCmdResetQueryPool(cmd, pool, slot * kPairs * 2, kPairs * 2);
+    s.used = true, s.up_sent = false;
+    for (int k = 0; k < 2; k++) {
+        Stream& st = s.s[k];
+        st.cmd = k ? upload : cmd;
+        st.base = (uint32_t)(slot * 2 + k) * kQ;
+        st.spans.clear();
+        st.outer = st.run = -1;
+        if (st.dirty) vkCmdResetQueryPool(st.cmd, pool, st.base, st.dirty);   // (an upload command buffer that is not sent resets nothing: its dirty stands)
+        st.nq = 0;
+    }
 }
 
-void gprof_begin(VkCommandBuffer cmd) {
-    if (!pool || cur < 0) return;
-    Slot& s = slots[cur];
-    if (s.open || s.labels.size() >= kPairs) return;
-    vkCmdWriteTimestamp2(cmd, VK_PIPELINE_STAGE_2_ALL_COMMANDS_BIT, pool, (uint32_t)(cur * kPairs + s.labels.size()) * 2);
-    s.open = true;
+void gprof_submitted(int slot, bool upload_sent) {
+    if (!pool || slot < 0 || slot >= kSlots) return;
+    slots[slot].up_sent = upload_sent;
 }
 
-void gprof_end(VkCommandBuffer cmd, const std::string& label) {
-    if (!pool || cur < 0) return;
-    Slot& s = slots[cur];
-    if (!s.open) return;
-    vkCmdWriteTimestamp2(cmd, VK_PIPELINE_STAGE_2_ALL_COMMANDS_BIT, pool,
-                         (uint32_t)(cur * kPairs + s.labels.size()) * 2 + 1);
-    s.labels.push_back(label);
-    s.open = false;
+bool gprof_begin(VkCommandBuffer cmd) {
+    Stream* st = find(cmd);
+    if (!st || st->outer >= 0 || st->nq + 4 > kQ) {
+        if (st && st->outer < 0) dropped++;
+        return false;
+    }
+    Span sp;
+    sp.qb = stamp(*st, cmd);
+    st->spans.push_back(std::move(sp));
+    st->outer = (int)st->spans.size() - 1;
+    return true;
+}
+
+void gprof_end(VkCommandBuffer cmd, const std::string& label, int items, uint64_t bytes) {
+    Stream* st = find(cmd);
+    if (!st || st->outer < 0) return;
+    const uint32_t q = stamp(*st, cmd);
+    if (st->run >= 0) st->spans[st->run].qe = q, st->run = -1;   // (the pass's last run ends with it)
+    Span& sp = st->spans[st->outer];
+    sp.qe = q, sp.label = label, sp.items = items, sp.bytes = bytes;
+    st->outer = -1;
+}
+
+void gprof_run(VkCommandBuffer cmd, uint64_t key) {
+    if (level() < 2) return;
+    Stream* st = find(cmd);
+    if (!st || st->outer < 0) return;
+    if (st->run >= 0 && st->run_key == key) {
+        st->spans[st->run].items++;
+        return;
+    }
+    if (st->nq + 3 > kQ) return;
+    const uint32_t q = stamp(*st, cmd);
+    if (st->run >= 0) st->spans[st->run].qe = q;
+    Span sp;
+    char l[32];
+    snprintf(l, sizeof l, "prog %016llx", (unsigned long long)key);
+    sp.label = l, sp.qb = q, sp.nested = true;
+    st->spans.push_back(std::move(sp));
+    st->run = (int)st->spans.size() - 1, st->run_key = key;
 }
 
 void gprof_collect(int slot) {
     if (!pool || slot < 0 || slot >= kSlots) return;
     Slot& s = slots[slot];
-    if (!s.used || s.labels.empty()) return;
-    std::vector<uint64_t> t(s.labels.size() * 2);
-    if (vkGetQueryPoolResults(dev.device, pool, slot * kPairs * 2, (uint32_t)t.size(), t.size() * 8, t.data(), 8,
-                              VK_QUERY_RESULT_64_BIT) != VK_SUCCESS)
-        return;
+    if (!s.used) return;
+    s.used = false;
     const double period = dev.props.limits.timestampPeriod;
-    for (size_t i = 0; i < s.labels.size(); i++) {
-        if (t[2 * i + 1] <= t[2 * i]) continue;
-        auto& e = totals[s.labels[i]];
-        e.first += (double)(t[2 * i + 1] - t[2 * i]) * period;
-        e.second++;
+    for (int k = 0; k < 2; k++) {
+        Stream& st = s.s[k];
+        if (k == 0 || s.up_sent) st.dirty = st.nq;   // (the next use resets what this one wrote)
+        if (st.spans.empty() || st.nq == 0 || (k && !s.up_sent)) {
+            st.spans.clear();
+            continue;
+        }
+        std::vector<uint64_t> t(st.nq);
+        if (vkGetQueryPoolResults(dev.device, pool, st.base, st.nq, t.size() * 8, t.data(), 8, VK_QUERY_RESULT_64_BIT) != VK_SUCCESS) {
+            st.spans.clear();
+            continue;
+        }
+        uint64_t first = UINT64_MAX, last = 0;
+        double sum = 0;
+        for (const Span& sp : st.spans) {
+            if (sp.label.empty() || sp.qb >= st.nq || sp.qe >= st.nq || t[sp.qe] <= t[sp.qb]) continue;
+            const double ns = (double)(t[sp.qe] - t[sp.qb]) * period;
+            Agg& a = totals[k][sp.label];
+            a.ns += ns, a.n++, a.items += sp.items, a.bytes += sp.bytes;
+            if (sp.nested) continue;
+            sum += ns;
+            first = std::min(first, t[sp.qb]), last = std::max(last, t[sp.qe]);
+        }
+        if (last > first) {
+            active_ns[k] += (double)(last - first) * period;
+            sum_ns[k] += sum;
+            recs[k]++;
+        }
+        st.spans.clear();
     }
-    s.labels.clear();
-    s.used = false;
 }
 
 void gprof_report(int frames) {
-    if (!pool || totals.empty()) return;
-    std::vector<std::pair<std::string, std::pair<double, int64_t>>> v(totals.begin(), totals.end());
-    std::sort(v.begin(), v.end(), [](const auto& a, const auto& b) { return a.second.first > b.second.first; });
-    double all = 0;
-    for (const auto& e : v) all += e.second.first;
-    logf("vk: GPU profile: %.2f ms a frame in %zu kinds of span; the most:", all / frames / 1e6, v.size());
-    for (size_t i = 0; i < v.size() && i < 25; i++)
-        logf("vk:   %6.3f ms  %5.1f a frame  %s", v[i].second.first / frames / 1e6, (double)v[i].second.second / frames,
-             v[i].first.c_str());
-    totals.clear();
+    if (!pool) return;
+    acc_frames += frames;
+    if (acc_frames < 600) return;
+    const double f = acc_frames, mb = 1048576.0;
+    logf("vk: GPU pass timing, %d presents, per frame (each timestamp waits for the GPU to finish what came before it: spans add up to "
+         "more than an unprofiled frame; read the shares):", acc_frames);
+    logf("vk:   %.2f ms a frame in all (recordings' command buffers + upload command buffers; the present's blit to the window is not timed; "
+         "the 'GPU time' line of an unprofiled run counts the first kind only)", (active_ns[0] + active_ns[1]) / f / 1e6);
+    logf("vk:   recordings' command buffers: %.2f ms from the first timestamp to the last in %.1f a frame (%.2f ms in spans, %.2f ms "
+         "between them: glue the spans do not name)", active_ns[0] / f / 1e6, recs[0] / f, sum_ns[0] / f / 1e6,
+         (active_ns[0] - sum_ns[0]) / f / 1e6);
+    logf("vk:   upload command buffers: %.2f ms in %.1f a frame (%.2f ms in spans, %.2f ms between them: texture uploads and "
+         "decodes, the page table, glue)", active_ns[1] / f / 1e6, recs[1] / f, sum_ns[1] / f / 1e6,
+         (active_ns[1] - sum_ns[1]) / f / 1e6);
+    if (dropped) logf("vk:   %lld spans not timed (a command buffer's timestamps ran out)", (long long)dropped);
+    struct Row {
+        std::string name;
+        int k;
+        Agg a;
+    };
+    std::vector<Row> rows, cats, progs;
+    std::map<std::string, Agg> by_cat[2];
+    for (int k = 0; k < 2; k++)
+        for (const auto& [label, a] : totals[k]) {
+            if (label.compare(0, 5, "prog ") == 0) {
+                progs.push_back({label, k, a});
+                continue;
+            }
+            rows.push_back({label, k, a});
+            Agg& c = by_cat[k][label.substr(0, label.find(' '))];
+            c.ns += a.ns, c.n += a.n, c.items += a.items, c.bytes += a.bytes;
+        }
+    for (int k = 0; k < 2; k++)
+        for (const auto& [name, a] : by_cat[k]) cats.push_back({name, k, a});
+    const auto by_ns = [](const Row& a, const Row& b) { return a.a.ns > b.a.ns; };
+    std::sort(cats.begin(), cats.end(), by_ns);
+    std::sort(rows.begin(), rows.end(), by_ns);
+    std::sort(progs.begin(), progs.end(), by_ns);
+    logf("vk:   by kind (cb: m = recordings' command buffers, u = upload ones; items: draws of a pass, copies of a copy batch):");
+    for (const Row& c : cats)
+        logf("vk:     %c %-9s %7.3f ms %5.1f%%  %7.1f spans  %8.1f items  %7.2f MB  %7.1f us a span", c.k ? 'u' : 'm', c.name.c_str(),
+             c.a.ns / f / 1e6, 100.0 * c.a.ns / std::max(active_ns[c.k], 1.0), c.a.n / f, c.a.items / f, c.a.bytes / f / mb,
+             c.a.ns / std::max<int64_t>(c.a.n, 1) / 1e3);
+    logf("vk:   the 25 spans that took the most (ms a frame, spans a frame, us a span, items a frame, MB a frame):");
+    for (size_t i = 0; i < rows.size() && i < 25; i++) {
+        const Row& r = rows[i];
+        logf("vk:   %c %7.3f ms  %6.1f x  %7.1f us  %8.1f items  %6.2f MB  %s", r.k ? 'u' : 'm', r.a.ns / f / 1e6, r.a.n / f,
+             r.a.ns / std::max<int64_t>(r.a.n, 1) / 1e3, r.a.items / f, r.a.bytes / f / mb, r.name.c_str());
+    }
+    if (!progs.empty()) {
+        logf("vk:   the 20 programs whose runs of draws took the most (RX_VK_PASS_TIMING=2: a timestamp at each change of program):");
+        for (size_t i = 0; i < progs.size() && i < 20; i++) {
+            const Row& r = progs[i];
+            logf("vk:   %7.3f ms  %6.1f runs  %7.1f us a run  %8.1f draws  %6.2f us a draw  %s", r.a.ns / f / 1e6, r.a.n / f,
+                 r.a.ns / std::max<int64_t>(r.a.n, 1) / 1e3, r.a.items / f, r.a.ns / std::max<int64_t>(r.a.items, 1) / 1e3,
+                 r.name.c_str());
+        }
+    }
+    for (auto& t : totals) t.clear();
+    active_ns[0] = active_ns[1] = sum_ns[0] = sum_ns[1] = 0;
+    recs[0] = recs[1] = dropped = 0;
+    acc_frames = 0;
 }
 
 } // namespace mkwvk

gpu/vk/vk_gprof.h

@@ -1,6 +1,10 @@
-// GPU profile (diagnostics): RX_VK_GPU_PROFILE=1 times every pass and dispatch on the GPU (a timestamp after all the
-// work before it and one after its own), labelled by what it renders or dispatches, and every 120 presents logs the
-// labels that took the most GPU time a frame.
+// GPU profile (diagnostics): RX_VK_PASS_TIMING=1 (RX_VK_GPU_PROFILE=1 is the same) times the GPU's work with timestamps: every render
+// pass, compute dispatch, barrier, texture/buffer copy, mirror sync, write-back and uniform write of the recordings' command buffers,
+// and of their upload command buffers, each a pair of timestamps labelled by what it was. Every 600 presents it logs, per frame: the
+// kinds of span with their totals, and the labels that took the most GPU time.
+// RX_VK_PASS_TIMING=2: also the runs of consecutive draws of one program inside the passes ("prog" lines: GPU ms by program key).
+// A timestamp waits for the GPU to finish what came before it, so profiled spans add up to more than an unprofiled frame (the
+// passes are ordered by full barriers anyway; the overlap that narrower barriers would allow is not measured here).
 #pragma once
 
 #include <string>
@@ -10,14 +14,37 @@
 namespace mkwvk {
 
 bool gprof_on();
-/// A recording begins in slot (its earlier work is done: its timings are collected first)
-void gprof_begin_recording(int slot, VkCommandBuffer cmd);
-/// A timed span begins (outside a pass, or right after it began) / ends (its label: what it was)
-void gprof_begin(VkCommandBuffer cmd);
-void gprof_end(VkCommandBuffer cmd, const std::string& label);
+/// A recording begins in slot (its earlier work is done: its timings are collected first); the upload command buffer is the
+/// recording's other one (submitted ahead of cmd, only when it has work)
+void gprof_begin_recording(int slot, VkCommandBuffer cmd, VkCommandBuffer upload);
+/// The recording is going to the GPU (upload_sent: with its upload command buffer)
+void gprof_submitted(int slot, bool upload_sent);
+/// A timed span begins in cmd (one at a time a command buffer: false when one is open already, or cmd is not a profiled one);
+/// gprof_end closes it (its label: what it was; items: draws, copies...; bytes: copied)
+bool gprof_begin(VkCommandBuffer cmd);
+void gprof_end(VkCommandBuffer cmd, const std::string& label, int items = 1, uint64_t bytes = 0);
+/// A draw of program key into the open pass (RX_VK_PASS_TIMING=2): the run of draws of one program is timed
+void gprof_run(VkCommandBuffer cmd, uint64_t key);
 /// The slot's work completed: its spans are added to the totals
 void gprof_collect(int slot);
-/// Every 120 presents: the top labels a frame
+/// Every 120 presents (frames of them): every 600, the report
 void gprof_report(int frames);
 
+/// A span of a scope: closed by the destructor with its label (items and bytes set while it is open)
+struct GprofSpan {
+    VkCommandBuffer cmd;
+    const char* label;
+    int items = 1;
+    uint64_t bytes = 0;
+    bool on = false;
+    GprofSpan(VkCommandBuffer c, const char* l) : cmd(c), label(l) {
+        if (gprof_on()) on = gprof_begin(c);
+    }
+    ~GprofSpan() {
+        if (on) gprof_end(cmd, label, items, bytes);
+    }
+    GprofSpan(const GprofSpan&) = delete;
+    GprofSpan& operator=(const GprofSpan&) = delete;
+};
+
 } // namespace mkwvk