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