Warn on long OPAL calls

Measure entry/exit time for OPAL calls and warn appropriately if the calls take too long (>100ms gets us a DEBUG log, > 1000ms gets us a warning). Signed-off-by: Stewart Smith <[email protected]>
dcrowell77 · Nov 22, 2018 · 50ea35c · 50ea35c
1 parent 8a2f8a3
commit 50ea35c
Show file tree

Hide file tree

Showing 2 changed files with 10 additions and 0 deletions.
diff --git a/core/opal.c b/core/opal.c
@@ -167,6 +167,7 @@ int64_t opal_entry_check(struct stack_frame *eframe)
 		}
 	}
 
+	cpu->entered_opal_call_at = mftb();
 	return OPAL_SUCCESS;
 }
 
@@ -176,6 +177,8 @@ int64_t opal_exit_check(int64_t retval, struct stack_frame *eframe)
 {
 	struct cpu_thread *cpu = this_cpu();
 	uint64_t token = eframe->gpr[0];
+	uint64_t now = mftb();
+	uint64_t call_time = tb_to_msecs(now - cpu->entered_opal_call_at);
 
 	if (!cpu->in_opal_call) {
 		disable_fast_reboot("Un-accounted firmware entry");
@@ -193,6 +196,12 @@ int64_t opal_exit_check(int64_t retval, struct stack_frame *eframe)
 			drop_my_locks(true);
 		}
 	}
+
+	if (call_time > 100) {
+		prlog((call_time < 1000) ? PR_DEBUG : PR_WARNING,
+		      "Spent %llu msecs in OPAL call %llu!\n",
+		      call_time, token);
+	}
 	return retval;
 }
 

diff --git a/include/cpu.h b/include/cpu.h
@@ -62,6 +62,7 @@ struct cpu_thread {
 	void				*icp_regs;
 	uint32_t			in_opal_call;
 	uint32_t			quiesce_opal_call;
+	uint64_t entered_opal_call_at;
 	uint32_t			con_suspend;
 	struct list_head		locks_held;
 	bool				con_need_flush;