[0.1.27] gpu-bench: a memory trace per step, -ocr-workers and -ort-log

Each result now has the GPU's memory over the baseline after loading, the
first image, each warm-up pass and each timed pass (with the pass's peak), in
the output and as trace= in the results file, so growth across passes (a leak)
shows apart from a working set. -ocr-workers sets OCR's GPU worker threads, and
-ort-log info prints onnxruntime's arena extensions: what found the cause of
0.1.24's memory fix.

check_targets.jai

@@ -47,7 +47,7 @@ APP_NAME        :: "mcap";
 APP_FOLDER_NAME :: "mcap";
 GIT_BRANCH    :: "check";
 GIT_HASH      :: "-";
-VERSION       :: "0.1.26";
+VERSION       :: "0.1.27";
 BUILD_DATE    :: "-";
 DEBUG         :: true;
 COMPILE_TESTS :: true;

first.jai

@@ -8,7 +8,7 @@ APP_NAME              :: "mcap";
 APP_FOLDER_NAME       :: "mcap";
 APP_BUNDLE_IDENTIFIER :: "com.example.mcap";
 
-VERSION :: "0.1.26";
+VERSION :: "0.1.27";
 // Where everything goes: bin/, or bin-headless/ for builds made with no_crash_dialog, so automated
 // builds never write over the ones you run by hand.
 build_directory := "bin";

tools/gpu_bench/gpu_bench.jai

@@ -19,10 +19,12 @@
 //   -out       where the results file goes (default gpu-bench-results beside this program)
 //   -note      a few words kept with the results, such as "plugged in, max performance"
 //   -progress  also print @progress lines, for the GPU Benchmark window
+//   -ocr-workers N  OCR's worker threads on the GPU, in place of Ocr_Options' (for investigating memory)
+//   -ort-log LEVEL  onnxruntime's console log: verbose, info (each GPU arena extension), warning (default)
 //
 // Build: jai first.jai - release (it is built with mcap on the gpu-bench branch).
 
-USAGE :: "Usage: gpu-bench [-only ocr,labels,segment] [-models a,b] [-repeats N] [-warmup N] [-cpu | -cpu-only] [-corpus FOLDER] [-out FOLDER] [-note TEXT] [-progress]\n";
+USAGE :: "Usage: gpu-bench [-only ocr,labels,segment] [-models a,b] [-repeats N] [-warmup N] [-cpu | -cpu-only] [-corpus FOLDER] [-out FOLDER] [-note TEXT] [-progress] [-ocr-workers N] [-ort-log LEVEL]\n";
 
 options: struct {
   only: [..] string;
@@ -32,6 +34,7 @@ options: struct {
   gpu := true;
   cpu := false;
   progress := false;
+  ocr_workers: s32;   // 0: Ocr_Options' default
   corpus_folder, out_folder, note: string;
 };
 
@@ -56,6 +59,15 @@ main :: () {
       case "-out";      options.out_folder = value; i += 2;
       case "-note";     options.note = value; i += 2;
       case "-progress"; options.progress = true; i += 1;
+      case "-ocr-workers"; options.ocr_workers = cast(s32) max(1, string_to_int(value)); i += 2;
+      case "-ort-log";
+        if value == {
+          case "verbose"; ort.log_level = .ORT_LOGGING_LEVEL_VERBOSE;
+          case "info";    ort.log_level = .ORT_LOGGING_LEVEL_INFO;
+          case "warning"; ort.log_level = .ORT_LOGGING_LEVEL_WARNING;
+          case;           print("-ort-log takes verbose, info or warning.\n"); exit(2);
+        }
+        i += 2;
       case "-help";     print(USAGE); exit(0);
       case;             print("Unknown option %.\n%", arg, USAGE); exit(2);
     }
@@ -139,12 +151,14 @@ Run :: struct {
   stages: string;          // where the time went, per item
   batch: s64;
   gpu: Gpu_Stats;
+  trace: [..] string;      // the GPU's memory above the baseline, MB, after each step: load:812 first:1020 warm1:... pass1:.../peak...
   explanation: string;     // why a GPU run is on the CPU
 }
 
 Gpu_Stats :: struct {
   sampled: bool;
   baseline_mb, peak_mb: float64;   // device memory before the engine, and the most during the timed passes
+  pass_peak_mb: float64;           // the most during the current timed pass
   util_sum, power_sum, clock_sum: float64;
   temperature_max: float64;
   samples: s64;
@@ -300,7 +314,9 @@ run_task :: (task: *Task, prefer_gpu: bool, corpus: *Corpus) -> Run {
   phrase_vectors: [] float;
   if task.kind == {
     case .OCR;
-      engine.ocr, ok, error = ocr_create(task.models_folder, task.model, prefer_gpu);
+      ocr_options: Ocr_Options;
+      if options.ocr_workers  ocr_options.gpu_workers = options.ocr_workers;
+      engine.ocr, ok, error = ocr_create(task.models_folder, task.model, prefer_gpu, ocr_options);
       if ok {
         ocr_gpu, ocr_why := ocr_gpu_status(engine.ocr);
         if prefer_gpu && !ocr_gpu  run.explanation = copy_string(ocr_why);
@@ -327,6 +343,7 @@ run_task :: (task: *Task, prefer_gpu: bool, corpus: *Corpus) -> Run {
       }
   }
   run.load_s = seconds_since(load_start);
+  trace(*run, "load");
   if !ok { sampler_stop(); run.error = copy_string(error); return run; }
   defer {
     ocr_destroy(engine.ocr);
@@ -413,10 +430,12 @@ run_task :: (task: *Task, prefer_gpu: bool, corpus: *Corpus) -> Run {
   first_start := current_time_monotonic();
   pass(true);
   run.first_s = seconds_since(first_start);
+  trace(*run, "first");
   reset_temporary_storage();
   for 1..options.warmup {
     progress(task.name, run.provider, "warm-up", it, options.warmup);
     pass(false);
+    trace(*run, tprint("warm%", it));
     reset_temporary_storage();
   }
   if task.kind == .OCR      ocr_reset_stats(engine.ocr);
@@ -426,8 +445,10 @@ run_task :: (task: *Task, prefer_gpu: bool, corpus: *Corpus) -> Run {
   for 1..options.repeats {
     progress(task.name, run.provider, "timing", it, options.repeats);
     start := current_time_monotonic();
+    sampler_pass_start();
     output, digest := pass(false);
     array_add(*run.pass_s, seconds_since(start));
+    trace(*run, tprint("pass%", it), sampler_pass_peak());
     if it == 1 { run.output = copy_string(output); run.digest = copy_string(short(digest)); }
     reset_temporary_storage();
   }
@@ -483,6 +504,7 @@ print_run :: (task: *Task, run: Run) {
   if run.gpu.samples  print("   GPU: % MB more memory at the peak, % percent busy, % W, % MHz, up to % C\n",
                             FF(run.gpu.peak_mb - run.gpu.baseline_mb, 0), FF(run.gpu.util_sum / run.gpu.samples, 0),
                             FF(run.gpu.power_sum / run.gpu.samples, 0), FF(run.gpu.clock_sum / run.gpu.samples, 0), FF(run.gpu.temperature_max, 0));
+  if run.trace.count  print("   GPU memory over the baseline (MB), after each step [and its peak]: %\n", join(..run.trace, " ",, temp));
   print("   found % (digest %)\n\n", run.output, run.digest);
 }
 
@@ -529,6 +551,7 @@ write_results :: (info: System_Info, started_at: Apollo_Time, corpus: *Corpus, t
                        FF(g.power_sum / g.samples, 0), FF(g.clock_sum / g.samples, 0), FF(g.temperature_max, 0));
     }
     if run.stages  print_to_builder(*b, " stages=%", run.stages);
+    if run.trace.count  print_to_builder(*b, " trace=%", join(..run.trace, ",",, temp));
     print_to_builder(*b, " output=% digest=%\n", run.output, run.digest);
   }
   name := tprint("%_%-%-%_%-%-%.txt", file_safe(info.machine), date.year, pad2(date.month_starting_at_0 + 1), pad2(date.day_of_month_starting_at_0 + 1),
@@ -572,6 +595,7 @@ sampler_start :: (stats: *Gpu_Stats) {
       if ok && !sampler.paused && sampler.running {
         g := sampler.stats;
         g.peak_mb = max(g.peak_mb, s.memory_used_mb);
+        g.pass_peak_mb = max(g.pass_peak_mb, s.memory_used_mb);
         g.util_sum += s.util_percent;
         g.power_sum += s.power_w;
         g.clock_sum += s.sm_clock_mhz;
@@ -585,6 +609,26 @@ sampler_start :: (stats: *Gpu_Stats) {
   thread_start(*sampler.thread);
 }
 
+// The GPU's memory now, over the run's baseline, as a step of its trace; with the step's peak when known.
+trace :: (run: *Run, step: string, peak: float64 = -1) {
+  if !run.gpu.sampled  return;
+  s, ok := gpu_sample();
+  if !ok  return;
+  now := s.memory_used_mb - run.gpu.baseline_mb;
+  if peak >= 0  array_add(*run.trace, sprint("%:%[%]", step, FF(now, 0), FF(peak - run.gpu.baseline_mb, 0)));
+  else          array_add(*run.trace, sprint("%:%", step, FF(now, 0)));
+}
+
+// The peak of one timed pass: reset as it starts, read as it ends.
+sampler_pass_start :: () { if !sampler.running  return; lock(*sampler.mutex); sampler.stats.pass_peak_mb = 0; unlock(*sampler.mutex); }
+sampler_pass_peak :: () -> float64 {
+  if !sampler.running  return -1;
+  lock(*sampler.mutex);
+  peak := sampler.stats.pass_peak_mb;
+  unlock(*sampler.mutex);
+  return peak;
+}
+
 sampler_pause  :: () { if !sampler.running  return; lock(*sampler.mutex); sampler.paused = true;  unlock(*sampler.mutex); }
 sampler_resume :: () { if !sampler.running  return; lock(*sampler.mutex); sampler.paused = false; unlock(*sampler.mutex); }