[Skiboot] [PATCH] Warn on long OPAL calls

[Stewart Smith]

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 <stewart at linux.ibm.com>
---
 core/opal.c   | 9 +++++++++
 include/cpu.h | 1 +
 2 files changed, 10 insertions(+)

diff --git a/core/opal.c b/core/opal.c
index 63a08510fef7..2834b38e02b0 100644
--- 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
index 2fe47982b8e4..851fb8e808f9 100644
--- 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;
-- 
2.19.1