feat: add verbose logging and log-level selection (#1941)

src/core/ggml_extend.hpp

@@ -63,7 +63,7 @@ __STATIC_INLINE__ int align_up(int n, int multiple) {
 __STATIC_INLINE__ void ggml_log_callback_default(ggml_log_level level, const char* text, void*) {
     switch (level) {
         case GGML_LOG_LEVEL_DEBUG:
-            LOG_DEBUG(text);
+            LOG_VERBOSE(text);
             break;
         case GGML_LOG_LEVEL_INFO:
             LOG_INFO(text);
@@ -75,7 +75,7 @@ __STATIC_INLINE__ void ggml_log_callback_default(ggml_log_level level, const cha
             LOG_ERROR(text);
             break;
         default:
-            LOG_DEBUG(text);
+            LOG_VERBOSE(text);
     }
 }
 
@@ -346,7 +346,7 @@ __STATIC_INLINE__ ggml_tensor* load_tensor_from_file(ggml_context* ctx, const st
     file.read(reinterpret_cast<char*>(&length), sizeof(length));
     file.read(reinterpret_cast<char*>(&ttype), sizeof(ttype));
 
-    LOG_DEBUG("load_tensor_from_file %d %d %d", n_dims, length, ttype);
+    LOG_VERBOSE("load_tensor_from_file %d %d %d", n_dims, length, ttype);
 
     if (file.eof()) {
         LOG_ERROR("incomplete file '%s'", file_path.c_str());
@@ -884,9 +884,9 @@ __STATIC_INLINE__ sd::Tensor<float> process_tiles_2d(const sd::Tensor<float>& in
     bool last_x     = false;
     float last_time = 0.0f;
     if (!silent) {
-        LOG_DEBUG("num tiles : %d, %d ", num_tiles_x, num_tiles_y);
-        LOG_DEBUG("optimal overlap : %f, %f (targeting %f)", tile_overlap_factor_x, tile_overlap_factor_y, tile_overlap_factor);
-        LOG_DEBUG("processing %i tiles", num_tiles);
+        LOG_VERBOSE("num tiles : %d, %d ", num_tiles_x, num_tiles_y);
+        LOG_VERBOSE("optimal overlap : %f, %f (targeting %f)", tile_overlap_factor_x, tile_overlap_factor_y, tile_overlap_factor);
+        LOG_VERBOSE("processing %i tiles", num_tiles);
         pretty_progress(0, num_tiles, 0.0f);
     }
     for (int y = 0; y < small_height && !last_y; y += non_tile_overlap_y) {
@@ -1436,7 +1436,7 @@ __STATIC_INLINE__ ggml_tensor* ggml_ext_attention_ext(ggml_context* ctx,
     };
 
     if (flash_attn) {
-        // LOG_DEBUG("attention_ext L_q:%d L_k:%d n_head:%d C:%d d_head:%d N:%d", L_q, L_k, n_head, C, d_head, N);
+        // LOG_VERBOSE("attention_ext L_q:%d L_k:%d n_head:%d C:%d d_head:%d N:%d", L_q, L_k, n_head, C, d_head, N);
         bool can_use_flash_attn = true;
         if (mask != nullptr) {
             // TODO: figure out if we can bend t5 to work too
@@ -1462,7 +1462,7 @@ __STATIC_INLINE__ ggml_tensor* ggml_ext_attention_ext(ggml_context* ctx,
 
     if (kqv == nullptr) {
         // if (flash_attn) {
-        //     LOG_DEBUG("fallback to default attention, L_q:%d L_k:%d n_head:%d C:%d d_head:%d N:%d", L_q, L_k, n_head, C, d_head, N);
+        //     LOG_VERBOSE("fallback to default attention, L_q:%d L_k:%d n_head:%d C:%d d_head:%d N:%d", L_q, L_k, n_head, C, d_head, N);
         // }
         v = ggml_ext_cont(ctx, ggml_permute(ctx, v, 1, 2, 0, 3));  // [N, n_kv_head, d_head, L_k]
         v = ggml_reshape_3d(ctx, v, L_k, d_head, n_kv_head * N);   // [N * n_kv_head, d_head, L_k]
@@ -2255,10 +2255,10 @@ protected:
                          graph_params.size());
                 graph_cut_layer_split_primary_notice_logged_ = true;
             } else {
-                LOG_DEBUG("%s graph-cut layer split: graph has no mark_graph_cut segments; using primary backend %s for %zu graph params",
-                          get_desc().c_str(),
-                          sd::layer_split_backend_device_display_name(runtime_backend).c_str(),
-                          graph_params.size());
+                LOG_VERBOSE("%s graph-cut layer split: graph has no mark_graph_cut segments; using primary backend %s for %zu graph params",
+                            get_desc().c_str(),
+                            sd::layer_split_backend_device_display_name(runtime_backend).c_str(),
+                            graph_params.size());
             }
             return true;
         }

src/core/ggml_extend_backend.cpp

@@ -392,7 +392,7 @@ static bool backend_name_exists(const std::string& name) {
 
 static ggml_backend_t init_named_backend(const std::string& name) {
     ggml_backend_load_all_once();
-    LOG_DEBUG("Initializing backend: %s", name.c_str());
+    LOG_VERBOSE("Initializing backend: %s", name.c_str());
     if (trim_copy(name).empty()) {
         return ggml_backend_init_best();
     }
@@ -542,10 +542,10 @@ static ggml_backend_t sd_get_default_backend() {
         if (dev_count == 0) {
             LOG_ERROR("No devices found!");
         } else {
-            LOG_DEBUG("Found %zu backend devices:", dev_count);
+            LOG_VERBOSE("Found %zu backend devices:", dev_count);
             for (size_t i = 0; i < dev_count; ++i) {
                 auto dev = ggml_backend_dev_get(i);
-                LOG_DEBUG("#%zu: %s", i, ggml_backend_dev_name(dev));
+                LOG_VERBOSE("#%zu: %s", i, ggml_backend_dev_name(dev));
             }
         }
     });
@@ -587,7 +587,7 @@ static ggml_backend_t sd_get_default_backend() {
     }
 
     if (sd_backend_is_cpu(backend)) {
-        LOG_DEBUG("Using CPU backend");
+        LOG_VERBOSE("Using CPU backend");
     }
 
     return backend;

src/core/ggml_runner.cpp

@@ -170,8 +170,8 @@ std::optional<Tensor<float>> GGMLRunner::execute_graph(ggml_cgraph* graph, int n
     }
     const bool segments_changed = plan.segments.size() != logged_segment_count_;
     if (segments_changed && (segmented || logged_segment_count_ > 1)) {
-        LOG_DEBUG("%s using %zu segment%s", get_desc().c_str(),
-                  plan.segments.size(), plan.segments.size() == 1 ? "" : "s");
+        LOG_VERBOSE("%s using %zu segment%s", get_desc().c_str(),
+                    plan.segments.size(), plan.segments.size() == 1 ? "" : "s");
     }
     SegmentGraphBindings bindings(cut_cache_, plan, graph);
     SegmentWeightPipeline weights(manager, runtime_backend, reinterpret_cast<uintptr_t>(this),
@@ -261,6 +261,8 @@ std::optional<Tensor<float>> GGMLRunner::execute_graph(ggml_cgraph* graph, int n
         if (!prefetch_requests.empty()) {
             weights.enqueue_next(index, prefetch_requests.front());
         }
+        LOG_DEBUG("%s executing segment %zu/%zu: %s", get_desc().c_str(),
+                  index + 1, plan.segments.size(), segment.group_name.c_str());
         if (!execute_segment(segment_graph, n_threads) ||
             !cache_.capture(segment_graph) ||
             !cut_cache_.capture(graph, segment, get_desc().c_str())) {
@@ -284,10 +286,10 @@ std::optional<Tensor<float>> GGMLRunner::execute_graph(ggml_cgraph* graph, int n
     }
     if (segments_changed || peak_compute_bytes != logged_compute_bytes_) {
         for (const auto& entry : peak_compute_bytes) {
-            LOG_DEBUG("%s compute buffer size: %.2f MB(%s) on %s (peak across %zu segment%s)",
-                      get_desc().c_str(), entry.second / (1024.0 * 1024.0),
-                      sd_backend_is_cpu(entry.first) ? "RAM" : "VRAM", ggml_backend_name(entry.first),
-                      plan.segments.size(), plan.segments.size() == 1 ? "" : "s");
+            LOG_VERBOSE("%s compute buffer size: %.2f MB(%s) on %s (peak across %zu segment%s)",
+                        get_desc().c_str(), entry.second / (1024.0 * 1024.0),
+                        sd_backend_is_cpu(entry.first) ? "RAM" : "VRAM", ggml_backend_name(entry.first),
+                        plan.segments.size(), plan.segments.size() == 1 ? "" : "s");
         }
         logged_compute_bytes_ = std::move(peak_compute_bytes);
         logged_segment_count_ = plan.segments.size();

src/core/layer_split_partition.cpp

@@ -251,13 +251,13 @@ namespace sd {
                          assignment.tensors_by_backend[i].size(),
                          assignment.bytes_by_backend[i] / (1024.0 * 1024.0));
             } else {
-                LOG_DEBUG("%s graph-cut layer split: %s <- segments [%zu, %zu), %zu tensors, %.1f MB",
-                          desc,
-                          layer_split_backend_device_display_name(split_backends[i]).c_str(),
-                          first_segment,
-                          last_segment,
-                          assignment.tensors_by_backend[i].size(),
-                          assignment.bytes_by_backend[i] / (1024.0 * 1024.0));
+                LOG_VERBOSE("%s graph-cut layer split: %s <- segments [%zu, %zu), %zu tensors, %.1f MB",
+                            desc,
+                            layer_split_backend_device_display_name(split_backends[i]).c_str(),
+                            first_segment,
+                            last_segment,
+                            assignment.tensors_by_backend[i].size(),
+                            assignment.bytes_by_backend[i] / (1024.0 * 1024.0));
             }
         }
     }

src/core/util.h

@@ -105,6 +105,7 @@ void* sd_get_backend_eval_callback_data();
 bool sd_backend_is(ggml_backend_t backend, const std::string& name);
 
 #define LOG_DEBUG(format, ...) log_printf(SD_LOG_DEBUG, __FILE__, __LINE__, format, ##__VA_ARGS__)
+#define LOG_VERBOSE(format, ...) log_printf(SD_LOG_VERBOSE, __FILE__, __LINE__, format, ##__VA_ARGS__)
 #define LOG_INFO(format, ...) log_printf(SD_LOG_INFO, __FILE__, __LINE__, format, ##__VA_ARGS__)
 #define LOG_WARN(format, ...) log_printf(SD_LOG_WARN, __FILE__, __LINE__, format, ##__VA_ARGS__)
 #define LOG_ERROR(format, ...) log_printf(SD_LOG_ERROR, __FILE__, __LINE__, format, ##__VA_ARGS__)