Hack in some stats to understand what's going on in smp_send_ici()

src/system/kernel/scheduler/scheduler.cpp

@@ -12,7 +12,7 @@
 
 
 /*! The thread scheduler */
-
+#include <cmath>
 
 #include <OS.h>
 
@@ -92,12 +92,63 @@ scheduler_dump_thread_data(Thread* thread)
 	thread->scheduler_data->Dump();
 }
 
+static const size_t RECORD_LENGTH = 4096;
+static uint32 gCASAttempts[RECORD_LENGTH];
+static nanotime_t gSendICILatency[RECORD_LENGTH];
+static nanotime_t gProcessPendingLatency[RECORD_LENGTH];
+
+static int64 gIndex = -1;
+
+static int ici_stats(int argc, char **argv) {
+	int64 total_recordings = gIndex % RECORD_LENGTH;
+
+	uint32 total_cas_attempts = 0;
+	uint32 max_cas_attempts = 0;
+
+	nanotime_t total_send_ici_latency = 0;
+	nanotime_t max_send_ici_latency = 0;
+
+	nanotime_t total_process_pending_latency = 0;
+	nanotime_t max_process_pending_latency = 0;
+
+	for (int64 i = 0; i < total_recordings; ++i) {
+		max_cas_attempts = std::max(max_cas_attempts, gCASAttempts[i]);
+		total_cas_attempts += gCASAttempts[i];
+
+		max_send_ici_latency = std::max(max_send_ici_latency, gSendICILatency[i]);
+		total_send_ici_latency += gSendICILatency[i];
+
+		max_process_pending_latency = std::max(max_process_pending_latency, gProcessPendingLatency[i]);
+		total_process_pending_latency += gProcessPendingLatency[i];
+	}
+
+	kprintf("CAS attempts: avg=%ld, max=%d\n", total_cas_attempts / total_recordings, max_cas_attempts);
+	kprintf("Send ICI Latency: avg=%ldns, max=%ldns\n", total_send_ici_latency / total_recordings, max_send_ici_latency);
+	kprintf("Process pending latency: avg=%ldns, max=%ldns\n", total_process_pending_latency / total_recordings, max_process_pending_latency);
+
+	return 0;
+}
+
+void smp_send_ici_kwa(int32 targetCPU, int32 message, addr_t data, addr_t data2,
+					  addr_t data3, void* dataPointer, uint32 flags,
+					  uint32& cas_attempts, nanotime_t& send_ici_latency, nanotime_t& process_pending_latency);
+
 static void
 do_smp_send_ici(int32 targetCPU, int32 message, addr_t data, addr_t data2, addr_t data3,
 				void *data_ptr, uint32 flags)
 {
 	SCHEDULER_ENTER_FUNCTION();
-	smp_send_ici(targetCPU, message, data, data2, data3, data_ptr, flags);
+
+	uint32 cas_attempts = 0;
+	nanotime_t send_ici_latency = 0;
+	nanotime_t process_pending_latency = 0;
+
+	smp_send_ici_kwa(targetCPU, message, data, data2, data3, data_ptr, flags, cas_attempts, send_ici_latency, process_pending_latency);
+
+	int64 idx = atomic_add64(&gIndex, 1) % RECORD_LENGTH;
+	gCASAttempts[idx] = cas_attempts;
+	gSendICILatency[idx] = send_ici_latency;
+	gProcessPendingLatency[idx] = process_pending_latency;
 }
 
 static void do_notify_scheduler_listeners(Thread *thread)
@@ -733,6 +784,8 @@ scheduler_init()
 		" cache level%s\n", cpuCount, cpuCount != 1 ? "s" : "",
 		gCPUCacheLevelCount, gCPUCacheLevelCount != 1 ? "s" : "");
 
+	add_debugger_command_etc("icistats", &ici_stats, "Show ICI latency stats", "No arguments required", 0);
+
 #ifdef SCHEDULER_PROFILING
 	Profiling::Profiler::Initialize();
 #endif

src/system/kernel/smp.cpp

@@ -11,6 +11,7 @@
 
 /*! Functionality for symetrical multi-processors */
 
+#include <OS.h>
 
 #include <smp.h>
 
@@ -1131,6 +1132,78 @@ smp_send_ici(int32 targetCPU, int32 message, addr_t data, addr_t data2,
 	}
 }
 
+void
+smp_send_ici_kwa(int32 targetCPU, int32 message, addr_t data, addr_t data2,
+				 addr_t data3, void* dataPointer, uint32 flags,
+				 uint32& cas_attempts, nanotime_t& send_ici_latency, nanotime_t& process_pending_latency)
+{
+	// KWA: Investigate here
+	struct smp_msg *msg;
+
+	TRACE("smp_send_ici: target 0x%lx, mess 0x%lx, data 0x%lx, data2 0x%lx, "
+		"data3 0x%lx, ptr %p, flags 0x%lx\n", targetCPU, message, data, data2,
+		data3, dataPointer, flags);
+
+	if (sICIEnabled) {
+		int state;
+		int currentCPU;
+
+		// find_free_message leaves interrupts disabled
+		state = find_free_message(&msg);
+
+		currentCPU = smp_get_current_cpu();
+		if (targetCPU == currentCPU) {
+			return_free_message(msg);
+			restore_interrupts(state);
+			return; // nope, cant do that
+		}
+
+		// set up the message
+		msg->message = message;
+		msg->data = data;
+		msg->data2 = data2;
+		msg->data3 = data3;
+		msg->data_ptr = dataPointer;
+		msg->ref_count = 1;
+		msg->flags = flags;
+		msg->done = 0;
+
+		// stick it in the appropriate cpu's mailbox
+		struct smp_msg* next;
+		do {
+			++cas_attempts;
+			cpu_pause();
+			next = atomic_pointer_get(&sCPUMessages[targetCPU]);
+			msg->next = next;
+		} while (atomic_pointer_test_and_set(&sCPUMessages[targetCPU], msg,
+				next) != next);
+
+		{
+			nanotime_t start_time = system_time_nsecs();
+			arch_smp_send_ici(targetCPU);
+			send_ici_latency = system_time_nsecs() - start_time;
+		}
+
+		if ((flags & SMP_MSG_FLAG_SYNC) != 0) {
+			nanotime_t start_time = system_time_nsecs();
+
+			// wait for the other cpu to finish processing it
+			// the interrupt handler will ref count it to <0
+			// if the message is sync after it has removed it from the mailbox
+			while (msg->done == 0) {
+				process_all_pending_ici(currentCPU);
+				cpu_wait(&msg->done, 1);
+			}
+			// for SYNC messages, it's our responsibility to put it
+			// back into the free list
+			return_free_message(msg);
+
+			process_pending_latency = system_time_nsecs() - start_time;
+		}
+
+		restore_interrupts(state);
+	}
+}
 
 void
 smp_send_multicast_ici(CPUSet& cpuMask, int32 message, addr_t data,