diff --git a/ggml/src/ggml-cuda/ggml-cuda.cu b/ggml/src/ggml-cuda/ggml-cuda.cu index 3cb4e07b48ff..8465ebc450ba 100644 --- a/ggml/src/ggml-cuda/ggml-cuda.cu +++ b/ggml/src/ggml-cuda/ggml-cuda.cu @@ -5424,6 +5424,90 @@ static int ggml_cuda_try_fuse(ggml_backend_cuda_context * cuda_ctx, ggml_cgraph return 0; } +// GGML_CUDA_OP_TIMING=1 (with CUDA graphs off): an event on the main stream before every node that launches work +// (views and no-ops get none); the time to the next event is charged to that node (a fused group to its first +// node). Events come from a pool and are read back only for the report, every 100 graphs, so the stream does not +// stop after each graph. The key of a node is kept as numbers: the graph's tensors can be gone at report time. +struct ggml_cuda_op_timing { + struct rec { + cudaEvent_t ev; + const char * desc; // nullptr: the end of a graph + ggml_type type0; + int64_t ne00; + int64_t ne01; + int64_t ne1; + bool mul_mat; + }; + + std::vector pool; + std::vector recs; + int64_t n_graphs = 0; + + cudaEvent_t next_event() { + const size_t i = recs.size(); + if (i == pool.size()) { + cudaEvent_t e; + CUDA_CHECK(cudaEventCreate(&e)); + pool.push_back(e); + } + return pool[i]; + } + + void record(const ggml_tensor * t, cudaStream_t stream) { + rec r = { next_event(), ggml_op_desc(t), t->src[0] ? t->src[0]->type : GGML_TYPE_COUNT, + t->src[0] ? t->src[0]->ne[0] : 0, t->src[0] ? t->src[0]->ne[1] : 0, t->ne[1], t->op == GGML_OP_MUL_MAT && t->src[0] }; + CUDA_CHECK(cudaEventRecord(r.ev, stream)); + recs.push_back(r); + } + + void end_graph(cudaStream_t stream) { + rec r = { next_event(), nullptr, GGML_TYPE_COUNT, 0, 0, 0, false }; + CUDA_CHECK(cudaEventRecord(r.ev, stream)); + recs.push_back(r); + if (++n_graphs < 100) { + return; + } + CUDA_CHECK(cudaEventSynchronize(r.ev)); + struct acc { double ms = 0; int64_t n = 0; }; + std::map totals; + double ms_graphs = 0.0; + for (size_t k = 0; k + 1 < recs.size(); ++k) { + const rec & a = recs[k]; + if (a.desc == nullptr) { + continue; + } + float ms = 0.0f; + CUDA_CHECK(cudaEventElapsedTime(&ms, a.ev, recs[k + 1].ev)); + char key[160]; + if (a.mul_mat) { + snprintf(key, sizeof(key), "MUL_MAT %s %lldx%lld cols=%lld", ggml_type_name(a.type0), + (long long) a.ne00, (long long) a.ne01, (long long) a.ne1); + } else { + snprintf(key, sizeof(key), "%s%s%s cols=%lld", a.desc, a.type0 != GGML_TYPE_COUNT ? " " : "", + a.type0 != GGML_TYPE_COUNT ? ggml_type_name(a.type0) : "", (long long) a.ne1); + } + auto & s = totals[key]; + s.ms += ms; + s.n += 1; + ms_graphs += ms; + } + 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_WARN("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_WARN(" %8.3f ms/graph %6.1f%% x%-7.1f %s\n", v[k].second.ms / n_graphs, + 100.0 * v[k].second.ms / ms_graphs, (double) v[k].second.n / n_graphs, v[k].first.c_str()); + } + recs.clear(); + n_graphs = 0; + } +}; + +static ggml_cuda_op_timing & ggml_cuda_op_timing_of(int device) { + static ggml_cuda_op_timing state[GGML_CUDA_MAX_DEVICES]; + return state[device]; +} + static void ggml_cuda_graph_evaluate_and_capture(ggml_backend_cuda_context * cuda_ctx, ggml_cgraph * cgraph, const bool use_cuda_graph, const bool cuda_graph_update_required, const void * graph_key) { bool graph_evaluated_or_captured = false; @@ -5577,6 +5661,10 @@ static void ggml_cuda_graph_evaluate_and_capture(ggml_backend_cuda_context * cud cuda_ctx->gdn_conv().reset(); + // GGML_CUDA_OP_TIMING=1: see ggml_cuda_op_timing + static const bool op_timing = getenv("GGML_CUDA_OP_TIMING") != nullptr; + const bool timing = op_timing && !use_cuda_graph; + for (int i = 0; i < cgraph->n_nodes; i++) { ggml_tensor * node = cgraph->nodes[i]; if (is_concurrent_event_active) { @@ -5623,6 +5711,10 @@ static void ggml_cuda_graph_evaluate_and_capture(ggml_backend_cuda_context * cud continue; } + if (timing) { + ggml_cuda_op_timing_of(cuda_ctx->device).record(node, cuda_ctx->stream(cuda_ctx->device, 0)); + } + // GDN decode conv chain: the conv-state gather moves into the fused launch at its CONCAT, which // also computes the conv-state CPY, SSM_CONV + SILU and the q/k L2_NORM (marked done) if (!cuda_ctx->gdn_conv().done.empty() && cuda_ctx->gdn_conv().done.count(node)) { @@ -5794,6 +5886,10 @@ static void ggml_cuda_graph_evaluate_and_capture(ggml_backend_cuda_context * cud try_launch_concurrent_event(node); } } + + if (timing) { + ggml_cuda_op_timing_of(cuda_ctx->device).end_graph(cuda_ctx->stream(cuda_ctx->device, 0)); + } } #ifdef USE_CUDA_GRAPH