Repository: li-plus/chatglm.cpp (language: python)

Issue:
Adding profiling info for chatglm.cpp
Hi, 
First of all, thanks for creating interesting project for ChatGLM.
I wonder if you plan to add performance profiling information similar to [llama_print_timings](https://github.com/ggerganov/llama.cpp/blob/b8c8dda75fdf5fdea49c80af36818e7c30fe0ddf/llama.cpp#L3432C6-L3432C25) in llama.cpp


Discussion / hints:
It's in schedule. Will collect performance results through something like a `PerfStreamer`.

Fix patch:
diff --git a/chatglm.cpp b/chatglm.cpp
index ea3bc21..d995b03 100644
--- a/chatglm.cpp
+++ b/chatglm.cpp
@@ -109,6 +109,18 @@ std::string to_string(ggml_tensor *tensor, bool with_data) {
 
 // ===== streamer =====
 
+void StreamerGroup::put(const std::vector<int> &output_ids) {
+    for (auto &streamer : streamers_) {
+        streamer->put(output_ids);
+    }
+}
+
+void StreamerGroup::end() {
+    for (auto &streamer : streamers_) {
+        streamer->end();
+    }
+}
+
 void TextStreamer::put(const std::vector<int> &output_ids) {
     if (is_prompt_) {
         // skip prompt
@@ -139,17 +151,47 @@ void TextStreamer::put(const std::vector<int> &output_ids) {
         print_len_ = text.size();
     }
 
-    std::cout << printable_text << std::flush;
+    os_ << printable_text << std::flush;
 }
 
 void TextStreamer::end() {
     std::string text = tokenizer_->decode(token_cache_);
-    std::cout << text.substr(print_len_) << std::endl;
+    os_ << text.substr(print_len_) << std::endl;
     is_prompt_ = true;
     token_cache_.clear();
     print_len_ = 0;
 }
 
+void PerfStreamer::put(const std::vector<int> &output_ids) {
+    CHATGLM_CHECK(!output_ids.empty());
+    if (num_prompt_tokens_ == 0) {
+        // before prompt eval
+        start_us_ = ggml_time_us();
+        num_prompt_tokens_ = output_ids.size();
+    } else {
+        if (num_output_tokens_ == 0) {
+            // first new token
+            prompt_us_ = ggml_time_us();
+        }
+        num_output_tokens_ += output_ids.size();
+    }
+}
+
+void PerfStreamer::reset() {
+    start_us_ = prompt_us_ = end_us_ = 0;
+    num_prompt_tokens_ = num_output_tokens_ = 0;
+}
+
+std::string PerfStreamer::to_string() const {
+    std::ostringstream oss;
+    oss << "prompt time: " << prompt_total_time_us() / 1000.f << " ms / " << num_prompt_tokens() << " tokens ("
+        << prompt_token_time_us() / 1000.f << " ms/token)\n"
+        << "output time: " << output_total_time_us() / 1000.f << " ms / " << num_output_tokens() << " tokens ("
+        << output_token_time_us() / 1000.f << " ms/token)\n"
+        << "total time: " << (prompt_total_time_us() + output_total_time_us()) / 1000.f << " ms";
+    return oss.str();
+}
+
 #ifdef _POSIX_MAPPED_FILES
 MappedFile::MappedFile(const std::string &path) {
     int fd = open(path.c_str(), O_RDONLY);
diff --git a/chatglm.h b/chatglm.h
index 02d3ee2..83375f7 100644
--- a/chatglm.h
+++ b/chatglm.h
@@ -162,20 +162,57 @@ class BaseStreamer {
     virtual void end() = 0;
 };
 
+class StreamerGroup : public BaseStreamer {
+  public:
+    StreamerGroup(std::vector<std::shared_ptr<BaseStreamer>> streamers) : streamers_(std::move(streamers)) {}
+    void put(const std::vector<int> &output_ids) override;
+    void end() override;
+
+  private:
+    std::vector<std::shared_ptr<BaseStreamer>> streamers_;
+};
+
 // reference: https://github.com/huggingface/transformers/blob/main/src/transformers/generation/streamers.py
 class TextStreamer : public BaseStreamer {
   public:
-    TextStreamer(BaseTokenizer *tokenizer) : tokenizer_(tokenizer), is_prompt_(true), print_len_(0) {}
+    TextStreamer(std::ostream &os, BaseTokenizer *tokenizer)
+        : os_(os), tokenizer_(tokenizer), is_prompt_(true), print_len_(0) {}
     void put(const std::vector<int> &output_ids) override;
     void end() override;
 
   private:
+    std::ostream &os_;
     BaseTokenizer *tokenizer_;
     bool is_prompt_;
     std::vector<int> token_cache_;
     int print_len_;
 };
 
+class PerfStreamer : public BaseStreamer {
+  public:
+    PerfStreamer() : start_us_(0), prompt_us_(0), end_us_(0), num_prompt_tokens_(0), num_output_tokens_(0) {}
+
+    void put(const std::vector<int> &output_ids) override;
+    void end() override { end_us_ = ggml_time_us(); }
+
+    void reset();
+    std::string to_string() const;
+
+    int64_t num_prompt_tokens() const { return num_prompt_tokens_; }
+    int64_t prompt_total_time_us() const { return prompt_us_ - start_us_; }
+    int64_t prompt_token_time_us() const { return prompt_total_time_us() / num_prompt_tokens(); }
+    int64_t num_output_tokens() const { return num_output_tokens_; }
+    int64_t output_total_time_us() const { return end_us_ - prompt_us_; }
+    int64_t output_token_time_us() const { return output_total_time_us() / num_output_tokens(); }
+
+  private:
+    int64_t start_us_;
+    int64_t prompt_us_;
+    int64_t end_us_;
+    int64_t num_prompt_tokens_;
+    int64_t num_output_tokens_;
+};
+
 class MappedFile {
   public:
     MappedFile(const std::string &path);
diff --git a/main.cpp b/main.cpp
index 47e1438..6e3a033 100644
--- a/main.cpp
+++ b/main.cpp
@@ -18,6 +18,7 @@ struct Args {
     float top_p = 0.7;
     float temp = 0.95;
     int num_threads = 0;
+    bool verbose = false;
 };
 
 void usage(const char *prog) {
@@ -34,7 +35,8 @@ void usage(const char *prog) {
               << "  --top_k N               top-k sampling (default: 0)\n"
               << "  --top_p N               top-p sampling (default: 0.7)\n"
               << "  --temp N                temperature (default: 0.95)\n"
-              << "  -t, --threads N         number of threads for inference\n";
+              << "  -t, --threads N         number of threads for inference\n"
+              << "  -v, --verbose           display verbose output including config/system/performance info\n";
 }
 
 static Args parse_args(int argc, char **argv) {
@@ -64,6 +66,8 @@ static Args parse_args(int argc, char **argv) {
             args.temp = std::stof(argv[++i]);
         } else if (arg == "-t" || arg == "--threads") {
             args.num_threads = std::stoi(argv[++i]);
+        } else if (arg == "-v" || arg == "--verbose") {
+            args.verbose = true;
         } else {
             std::cerr << "Unknown argument: " << arg << std::endl;
             usage(argv[0]);
@@ -107,10 +111,18 @@ static bool get_utf8_line(std::string &line) { return !!std::getline(std::cin, l
 #endif
 
 void chat(const Args &args) {
+    ggml_time_init();
+    int64_t start_load_us = ggml_time_us();
     chatglm::Pipeline pipeline(args.model_path);
+    int64_t end_load_us = ggml_time_us();
+
     std::string model_name = pipeline.model->type_name();
 
-    chatglm::TextStreamer streamer(pipeline.tokenizer.get());
+    auto text_streamer = std::make_shared<chatglm::TextStreamer>(std::cout, pipeline.tokenizer.get());
+    auto perf_streamer = std::make_shared<chatglm::PerfStreamer>();
+    auto streamer = std::make_shared<chatglm::StreamerGroup>(
+        std::vector<std::shared_ptr<chatglm::BaseStreamer>>{text_streamer, perf_streamer});
+
     chatglm::GenerationConfig gen_config(args.max_length, args.max_context_length, args.temp > 0, args.top_k,
                                          args.top_p, args.temp, args.num_threads);
 
@@ -125,7 +137,40 @@ void chat(const Args &args) {
                   << R"( / /___/ / / / /_/ / /_/ /_/ / /___/ /  / // /__/ /_/ / /_/ / )" << '\n'
                   << R"( \____/_/ /_/\__,_/\__/\____/_____/_/  /_(_)___/ .___/ .___/  )" << '\n'
                   << R"(                                              /_/   /_/       )" << '\n';
+    }
+
+    if (args.verbose) {
+        std::cout << "system info: | "
+                  << "AVX = " << ggml_cpu_has_avx() << " | "
+                  << "AVX2 = " << ggml_cpu_has_avx2() << " | "
+                  << "AVX512 = " << ggml_cpu_has_avx512() << " | "
+                  << "AVX512_VBMI = " << ggml_cpu_has_avx512_vbmi() << " | "
+                  << "AVX512_VNNI = " << ggml_cpu_has_avx512_vnni() << " | "
+                  << "FMA = " << ggml_cpu_has_fma() << " | "
+                  << "NEON = " << ggml_cpu_has_neon() << " | "
+                  << "ARM_FMA = " << ggml_cpu_has_arm_fma() << " | "
+                  << "F16C = " << ggml_cpu_has_f16c() << " | "
+                  << "FP16_VA = " << ggml_cpu_has_fp16_va() << " | "
+                  << "WASM_SIMD = " << ggml_cpu_has_wasm_simd() << " | "
+                  << "BLAS = " << ggml_cpu_has_blas() << " | "
+                  << "SSE3 = " << ggml_cpu_has_sse3() << " | "
+                  << "VSX = " << ggml_cpu_has_vsx() << " |\n";
+
+        std::cout << "inference config: | "
+                  << "max_length = " << args.max_length << " | "
+                  << "max_context_length = " << args.max_context_length << " | "
+                  << "top_k = " << args.top_k << " | "
+                  << "top_p = " << args.top_p << " | "
+                  << "temperature = " << args.temp << " | "
+                  << "num_threads = " << args.num_threads << " |\n";
+
+        std::cout << "loaded " << pipeline.model->type_name() << " model from " << args.model_path
+                  << " within: " << (end_load_us - start_load_us) / 1000.f << " ms\n";
 
+        std::cout << std::endl;
+    }
+
+    if (args.interactive) {
         std::vector<std::string> history;
         while (1) {
             std::cout << std::setw(model_name.size()) << std::left << "Prompt"
@@ -139,12 +184,19 @@ void chat(const Args &args) {
             }
             history.emplace_back(std::move(prompt));
             std::cout << model_name << " > ";
-            std::string output = pipeline.chat(history, gen_config, &streamer);
+            std::string output = pipeline.chat(history, gen_config, streamer.get());
             history.emplace_back(std::move(output));
+            if (args.verbose) {
+                std::cout << "\n" << perf_streamer->to_string() << "\n\n";
+            }
+            perf_streamer->reset();
         }
         std::cout << "Bye\n";
     } else {
-        pipeline.chat({args.prompt}, gen_config, &streamer);
+        pipeline.chat({args.prompt}, gen_config, streamer.get());
+        if (args.verbose) {
+            std::cout << "\n" << perf_streamer->to_string() << "\n\n";
+        }
     }
 }
 


Test patch:
diff --git a/chatglm_test.cpp b/chatglm_test.cpp
index a5f1674..3900eb5 100644
--- a/chatglm_test.cpp
+++ b/chatglm_test.cpp
@@ -923,34 +923,6 @@ TEST(Pipeline, ChatGLM2) {
     }
 }
 
-struct PerfStreamer : public BaseStreamer {
-    int64_t start_ms;
-    int64_t ctx_ms;
-    int64_t end_ms;
-    int64_t num_ctx_tokens;
-    int64_t num_new_tokens;
-
-    PerfStreamer() : start_ms(ggml_time_ms()), ctx_ms(0), end_ms(0), num_ctx_tokens(0), num_new_tokens(0) {}
-
-    void put(const std::vector<int> &output_ids) override {
-        CHATGLM_CHECK(!output_ids.empty());
-        if (num_ctx_tokens == 0) {
-            num_ctx_tokens = output_ids.size();
-        } else {
-            if (num_new_tokens == 0) {
-                ctx_ms = ggml_time_ms();
-            }
-            num_new_tokens += output_ids.size();
-        }
-    }
-    void end() override { end_ms = ggml_time_ms(); }
-
-    int64_t ms_ctx_tokens() const { return ctx_ms - start_ms; }
-    int64_t ms_per_ctx_token() const { return ms_ctx_tokens() / num_ctx_tokens; }
-    int64_t ms_new_tokens() const { return end_ms - ctx_ms; }
-    int64_t ms_per_new_token() const { return ms_new_tokens() / num_new_tokens; }
-};
-
 static void run_benchmark(const fs::path &model_path) {
     if (!fs::exists(model_path)) {
         GTEST_SKIP() << "Skipping benchmark test (model " << model_path << " not found)";
@@ -978,13 +950,10 @@ static void run_benchmark(const fs::path &model_path) {
     int64_t gen_s = (ggml_time_ms() - start_ms) / 1000.f;
 
     std::cout << "======== benchmark results for " << model_path.filename() << " ========\n"
-              << "Using #threads: " << gen_config.num_threads << "\n"
-              << "Model loaded within: " << load_model_ms << " ms\n"
-              << "Generation finished within: " << gen_s << " s\n"
-              << "Per ctx token latency: " << streamer.ms_per_ctx_token() << " ms/token (" << streamer.ms_ctx_tokens()
-              << " ms / " << streamer.num_ctx_tokens << " tokens)\n"
-              << "Per new token latency: " << streamer.ms_per_new_token() << " ms/token (" << streamer.ms_new_tokens()
-              << " ms / " << streamer.num_new_tokens << " tokens)\n"
+              << "using #threads: " << gen_config.num_threads << "\n"
+              << "model loaded within: " << load_model_ms << " ms\n"
+              << "generation finished within: " << gen_s << " s\n"
+              << streamer.to_string() << "\n"
               << "===========================================================\n";
 }