From 819054fee35e22fcece7e39283f40665c0bf9f2f Mon Sep 17 00:00:00 2001 From: Cary Palmer <24235924+professorpalmer@users.noreply.github.com> Date: Sun, 27 Sep 2026 02:34:55 -0500 Subject: [PATCH] cuda: GGML_CUDA_OP_TIMING=1 per-node GPU time breakdown With CUDA graphs off (GGML_CUDA_DISABLE_GRAPHS=1), records an event before every graph node on the main stream, charges the time to the next event to that node (a fused group to its first node), aggregates by op/type/shape and prints the top 30 every 100 graphs. Launch gaps inflate the small ops; the large mat-vecs read true. Diagnostics only; off by default. Co-Authored-By: Claude Opus 5.5 (cherry picked from commit 31640357451f9d370f49f4284b803295399e6c5c) --- ggml/src/ggml-cuda/ggml-cuda.cu | 56 +++++++++++++++++++++++++++++++++ 1 file changed, 56 insertions(+) diff --git a/ggml/src/ggml-cuda/ggml-cuda.cu b/ggml/src/ggml-cuda/ggml-cuda.cu index 41b3be6317d8..0b0b5ce08089 100644 --- a/ggml/src/ggml-cuda/ggml-cuda.cu +++ b/ggml/src/ggml-cuda/ggml-cuda.cu @@ -4519,8 +4519,20 @@ static void ggml_cuda_graph_evaluate_and_capture(ggml_backend_cuda_context * cud cuda_ctx->gdn_gathers().reset(); cuda_ctx->fwht_q8().reset(); + // GGML_CUDA_OP_TIMING=1 (with CUDA graphs off): an event on the main stream before every node; the + // time to the next event is charged to that node (a fused group to its first node). Printed below. + static const bool op_timing = getenv("GGML_CUDA_OP_TIMING") != nullptr; + const bool timing = op_timing && !use_cuda_graph; + std::vector> op_events; + for (int i = 0; i < cgraph->n_nodes; i++) { ggml_tensor * node = cgraph->nodes[i]; + if (timing) { + cudaEvent_t e; + CUDA_CHECK(cudaEventCreate(&e)); + CUDA_CHECK(cudaEventRecord(e, cuda_ctx->stream(cuda_ctx->device, 0))); + op_events.push_back({ node, e }); + } if (is_concurrent_event_active) { GGML_ASSERT(concurrent_event); @@ -4718,6 +4730,50 @@ static void ggml_cuda_graph_evaluate_and_capture(ggml_backend_cuda_context * cud try_launch_concurrent_event(node); } } + + if (timing && !op_events.empty()) { + cudaEvent_t end; + CUDA_CHECK(cudaEventCreate(&end)); + CUDA_CHECK(cudaEventRecord(end, cuda_ctx->stream(cuda_ctx->device, 0))); + CUDA_CHECK(cudaEventSynchronize(end)); + struct acc { double ms = 0; int64_t n = 0; }; + static std::map totals; + static int64_t n_graphs = 0; + static double ms_graphs = 0; + for (size_t k = 0; k < op_events.size(); ++k) { + float ms = 0.0f; + CUDA_CHECK(cudaEventElapsedTime(&ms, op_events[k].second, k + 1 < op_events.size() ? op_events[k + 1].second : end)); + const ggml_tensor * t = op_events[k].first; + char key[160]; + if (t->op == GGML_OP_MUL_MAT && t->src[0]) { + snprintf(key, sizeof(key), "MUL_MAT %s %lldx%lld cols=%lld", ggml_type_name(t->src[0]->type), + (long long) t->src[0]->ne[0], (long long) t->src[0]->ne[1], (long long) t->ne[1]); + } else { + snprintf(key, sizeof(key), "%s%s%s cols=%lld", ggml_op_desc(t), t->src[0] ? " " : "", + t->src[0] ? ggml_type_name(t->src[0]->type) : "", (long long) t->ne[1]); + } + auto & a = totals[key]; + a.ms += ms; + a.n += 1; + ms_graphs += ms; + } + for (auto & pe : op_events) { + CUDA_CHECK(cudaEventDestroy(pe.second)); + } + CUDA_CHECK(cudaEventDestroy(end)); + if (++n_graphs % 100 == 0) { + std::vector> v(totals.begin(), totals.end()); + std::sort(v.begin(), v.end(), [](auto & x, auto & y) { return x.second.ms > y.second.ms; }); + GGML_LOG_INFO("op timing over %lld graphs: %.3f ms per graph\n", (long long) n_graphs, ms_graphs / n_graphs); + for (size_t k = 0; k < v.size() && k < 30; ++k) { + GGML_LOG_INFO(" %8.3f ms/graph %6.1f%% x%-5lld %s\n", v[k].second.ms / n_graphs, + 100.0 * v[k].second.ms / ms_graphs, (long long) (v[k].second.n / n_graphs), v[k].first.c_str()); + } + totals.clear(); + n_graphs = 0; + ms_graphs = 0; + } + } } #ifdef USE_CUDA_GRAPH