kernel_tracing/bpftrace_scripts: improve timing accuracy and reduce o…

…verhead Removes high-volume printing and captures nsecs at probe entry Signed-off-by: Noah Klayman <noah.klayman@intel.com>
thesofproject · Jul 22, 2022 · 7fb8097 · 7fb8097
1 parent bf8e2e9
commit 7fb8097
Show file tree

Hide file tree

Showing 3 changed files with 15 additions and 10 deletions.
diff --git a/kernel_tracing/bpftrace_scripts/hda_irq_source_deltas.bt b/kernel_tracing/bpftrace_scripts/hda_irq_source_deltas.bt
@@ -4,10 +4,12 @@
 // This collects the deltas between irqs from each source
 
 tracepoint:sof_intel:sof_intel_hda_irq {
+  // Save time right away as it changes during bpftrace script execution
+  @nsecs = nsecs;
   if (@times[str(args->source)]) {
-    @delta_usecs[str(args->source)] = hist((nsecs - @times[str(args->source)]) / 1000);
+    @delta_usecs[str(args->source)] = hist((@nsecs - @times[str(args->source)]) / 1000);
   }
-  @times[str(args->source)] = nsecs;
+  @times[str(args->source)] = @nsecs;
 }
 
 END {

diff --git a/kernel_tracing/bpftrace_scripts/ipc_tx_time.bt b/kernel_tracing/bpftrace_scripts/ipc_tx_time.bt
@@ -6,25 +6,27 @@
 // when you stop the script with ctrl-c
 
 kprobe:sof_ipc_tx_message {
+  // Save time right away as it changes during bpftrace script execution
+  @nsecs = nsecs;
   if (@start != 0 ) {
     printf("ERROR: overlapping tx");
     exit();
   }
-  @start = nsecs;
+  @start = @nsecs;
   // We could get also the name of the device and other properties from the args,
   // but we'd need to enable DEBUG_INFO and DEBUG_INFO_BTF to get the types
   // It would allow us to sort timings by device for example
-  printf("tx started\n");
 }
 
 kretprobe:sof_ipc_tx_message {
-  printf("tx finished, took %d nsecs\n", nsecs - @start);
-  @usecs = hist((nsecs - @start) / 1000);
-  @avg = avg((nsecs - @start) / 1000);
+  @duration = nsecs - @start;
+  @usecs = hist(@duration / 1000);
+  @avg = avg(@duration / 1000);
   @start = 0;
 }
 
 END {
   // Clean up variables that shouldn't be printed
   delete(@start);
+  delete(@duration);
 }
diff --git a/kernel_tracing/bpftrace_scripts/suspend_resume_time.bt b/kernel_tracing/bpftrace_scripts/suspend_resume_time.bt
@@ -16,10 +16,11 @@ kprobe:sof_resume, kprobe:sof_suspend {
 }
 
 kretprobe:sof_resume, kretprobe:sof_suspend {
+  @duration = nsecs - @start;
   // When the function returns, we use the saved timestamp to determine execution time
-  printf("%s (%s) finished, took %d nsecs\n", probe, @type, nsecs - @start);
-  @usecs[probe, @type] = hist((nsecs - @start) / 1000);
-  @avg[probe, @type] = avg((nsecs - @start) / 1000);
+  printf("%s (%s) finished, took %d nsecs\n", probe, @type, @duration);
+  @usecs[probe, @type] = hist(@duration / 1000);
+  @avg[probe, @type] = avg(@duration / 1000);
 }
 
 END {