commit 1419dd05375a71fc5791606d438ee109402a909a
from: int16h <int16h@gmail.com>
date: Fri Dec  5 14:39:53 2025 UTC

Diag: added `yields` to console menu to display process yields/blocks; instrumented further and made service-to-service IPC waits block instead of busy yield

commit - 79729c5d4ed16722fe7477cfc4b40df21923ddfa
commit + 1419dd05375a71fc5791606d438ee109402a909a
blob - 94a71cb4192b0332491461bbad0974cda84e4b50
blob + 1b85ac9392d27383c40b00d9aedb19739b081aeb
--- kernel/console/service.c
+++ kernel/console/service.c
@@ -44,6 +44,8 @@ static size_t console_ctrl_head;
 static size_t console_ctrl_tail;
 static struct sched_task *console_task;
 static struct sched_task *console_service_task;
+static struct sched_task *console_waiter;
+static bool console_wait_flag;
 static ipc_portal_handle_t console_tty_portal = IPC_PORTAL_INVALID_HANDLE;
 static struct sched_task *console_tty_task;
 static ipc_portal_handle_t console_ttyctl_portal = IPC_PORTAL_INVALID_HANDLE;
@@ -70,6 +72,7 @@ static bool console_logged_deprecation;
 static spinlock_t line_queue_lock = SPINLOCK_INIT;
 static spinlock_t char_queue_lock = SPINLOCK_INIT;
 static spinlock_t ctrl_queue_lock = SPINLOCK_INIT;
+static spinlock_t console_wait_lock = SPINLOCK_INIT;
 
 static void	console_task_main(void *arg);
 static void	console_queue_push(const char *line);
@@ -101,6 +104,23 @@ void		console_service_ttyctl_send(const char *buf, siz
 
 #define CONSOLE_BLOCKTRACE_MAX 32U
 
+static void
+console_wake_service_task(void)
+{
+	struct sched_task *task = NULL;
+
+	spinlock_lock(&console_wait_lock);
+	console_wait_flag = true;
+	if (console_waiter != NULL) {
+		task = console_waiter;
+		console_waiter = NULL;
+	}
+	spinlock_unlock(&console_wait_lock);
+
+	if (task != NULL)
+		sched_wake(task);
+}
+
 static bool
 console_boot_banner_enabled(void)
 {
@@ -156,6 +176,8 @@ console_queue_push(const char *line)
 	console_q_tail++;
 
 	spinlock_unlock(&line_queue_lock);
+
+	console_wake_service_task();
 }
 
 static bool
@@ -254,6 +276,7 @@ console_service_control_event(enum console_pty_control
 		printk("\n");
 	}
 
+	console_wake_service_task();
 	sched_nudge_cpu(smp_current_cpu());
 }
 
@@ -573,7 +596,7 @@ console_process_line(const char *line)
 		return;
 	}
 	if (line_streq(line, "help")) {
-		serial_write("[console] commands: help, status, ticks, cpustats, perf, diag, blocktrace, next, activate <id>, ptys\n", 104);
+		serial_write("[console] commands: help, status, ticks, cpustats, yields, perf, diag, blocktrace, next, activate <id>, ptys\n", 111);
 		return;
 	}
 	if (line_streq(line, "status")) {
@@ -594,6 +617,12 @@ console_process_line(const char *line)
 		early_console_disable_serial_write();
 		return;
 	}
+	if (line_streq(line, "yields")) {
+		early_console_enable_serial_write();
+		sched_dump_yielders();
+		early_console_disable_serial_write();
+		return;
+	}
 	if (line_streq(line, "perf")) {
 		early_console_enable_serial_write();
 		perf_dump();
@@ -730,13 +759,15 @@ console_task_main(void *arg)
 		}
 		console_tty_drain_queue();
 		if (!queue_pop(&entry)) {
+			/* Drain any pending UART characters before sleeping. */
+			serial_poll_rx();
+
 			if (console_idle_debug < 4) {
 				#ifdef LENIX_DEBUG
 				printk("[console] idle, polling serial\n");
 				#endif
 				console_idle_debug++;
 			}
-			serial_poll_rx();
 			sched_yield();
 			continue;
 		}
@@ -860,6 +891,7 @@ console_tty_char_push(char c, uint32_t flags)
 	console_char_tail++;
 
 	spinlock_unlock(&char_queue_lock);
+	console_wake_service_task();
 	return true;
 }
 
blob - 542d22511ef07ed05dadde293d7aff087f6d4e2a
blob + 16b13cd94b436dfcddd2973c289ab756f8e49429
--- kernel/include/metrics/perf.h
+++ kernel/include/metrics/perf.h
@@ -8,6 +8,8 @@ enum perf_counter {
 	PERF_COUNTER_SCHED_TICKS = 0,
 	PERF_COUNTER_SCHED_CONTEXT_SWITCH,
 	PERF_COUNTER_SCHED_RESCHED_IPI,
+	PERF_COUNTER_SCHED_YIELD,
+	PERF_COUNTER_SCHED_BLOCK,
 	PERF_COUNTER_IPC_PORTAL_SEND,
 	PERF_COUNTER_IPC_PORTAL_RECV,
 	PERF_COUNTER_IPC_MAILBOX_ENQUEUE,
blob - 56fb98ba790d8bf0303025dbc80b293776abff90
blob + 0b035678f549d10ed635723092a1615a93bbb6bd
--- kernel/include/sched/task.h
+++ kernel/include/sched/task.h
@@ -84,6 +84,7 @@ void	sched_cpu_idle_loop(void) __attribute__((noreturn
 int	sched_task_enqueue_on(struct sched_task *, uint32_t cpu);
 void	sched_nudge_cpu(uint32_t cpu);
 void	sched_dump_telemetry(void);
+void	sched_dump_yielders(void);
 const char	*sched_current_task_name(void);
 
 /* Per-CPU state access (used by IPC subsystem) */
blob - 820a09a5d0ce833ca1851c8e6d434605cfe83829
blob + e53ae9251c89c46d65c613dc34e503e8decd0286
--- kernel/ipc/service_client.c
+++ kernel/ipc/service_client.c
@@ -22,6 +22,7 @@ struct pending_service_request {
 	ipc_portal_handle_t portal;  /* Portal handle used to send the request */
 	struct sched_task *server;   /* Target server task */
 	uint32_t token;              /* Request token */
+	struct sched_task *waiter;   /* Task waiting on the response */
 	struct ipc_service_pending *pending_slot;  /* Pointer to pending slot in client */
 };
 
@@ -198,6 +199,7 @@ ipc_service_request_issue_timeout(struct ipc_service_c
 	preq->server = ipc_portal_target(client->server_portal);
 	preq->token = slot->token;
 	preq->pending_slot = slot;
+	preq->waiter = sched_current_task();
 
 	/* Copy request to temporary buffer and set token */
 	/* Token is at offset 4 bytes (after opcode at offset 0) */
@@ -217,14 +219,17 @@ ipc_service_request_issue_timeout(struct ipc_service_c
 	/* Wait for response while yielding so other tasks can run */
 	spins = 0;
 	while (!__atomic_load_n(&slot->ready, __ATOMIC_ACQUIRE)) {
-		if (++spins > spin_limit) {
-			slot->in_use = false;
-			spinlock_lock(&pending_requests_lock);
-			preq->in_use = false;
-			spinlock_unlock(&pending_requests_lock);
-			return -1;
+		/*
+		 * Block after the first spin to avoid burning CPU while
+		 * waiting for the service to respond. The response path will
+		 * wake us via sched_wake() using the waiter recorded in preq.
+		 */
+		if (spins < spin_limit / 4) {
+			spins++;
+			sched_yield();
+			continue;
 		}
-		sched_yield();
+		sched_block_current();
 	}
 
 	/* Copy response to caller's buffer */
@@ -239,8 +244,10 @@ ipc_service_request_issue_timeout(struct ipc_service_c
 	if (preq->in_use &&
 	    preq->portal == client->server_portal &&
 	    preq->pending_slot == slot &&
-	    preq->token == slot->token)
+	    preq->token == slot->token) {
 		preq->in_use = false;
+		preq->waiter = NULL;
+	}
 	spinlock_unlock(&pending_requests_lock);
 	if (out_resp_len != NULL)
 		*out_resp_len = slot->response_len;
@@ -329,8 +336,13 @@ ipc_service_handle_response(ipc_portal_handle_t portal
 
 	/* Clean up the registry entry */
 	preq->in_use = false;
+	preq->waiter = NULL;
 
 	spinlock_unlock(&pending_requests_lock);
 
+	/* Wake the waiting client task (if any) now that the response is ready */
+	if (preq->waiter != NULL)
+		sched_wake(preq->waiter);
+
 	return 0;
 }
blob - 07bb52a98a8fc73e6bbba7603eb73d0138c8c508
blob + 5b89c59dfba5d914998d7db0a0c58fbf77ee5e7d
--- kernel/metrics/perf.c
+++ kernel/metrics/perf.c
@@ -18,6 +18,8 @@ static const char *const perf_counter_names[PERF_COUNT
 	[PERF_COUNTER_SCHED_TICKS] = "sched_ticks",
 	[PERF_COUNTER_SCHED_CONTEXT_SWITCH] = "sched_context_switches",
 	[PERF_COUNTER_SCHED_RESCHED_IPI] = "sched_resched_ipi",
+	[PERF_COUNTER_SCHED_YIELD] = "sched_yields",
+	[PERF_COUNTER_SCHED_BLOCK] = "sched_blocks",
 	[PERF_COUNTER_IPC_PORTAL_SEND] = "ipc_portal_send",
 	[PERF_COUNTER_IPC_PORTAL_RECV] = "ipc_portal_recv",
 	[PERF_COUNTER_IPC_MAILBOX_ENQUEUE] = "ipc_mailbox_enqueue",
blob - 09321e725d34d96ef760f81d4e6fe0c25db7b359
blob + f9f55a2bd2dcc13250def1b2a555cd10cc4b4b13
--- kernel/sched/task.c
+++ kernel/sched/task.c
@@ -75,6 +75,8 @@ struct sched_task {
 	uint64_t tgid;              /* Thread group leader (pid of leader) */
 	uint64_t pgrp;              /* Process group ID */
 	uint64_t sid;               /* Session ID */
+	uint64_t yield_count;
+	uint64_t block_count;
 	enum sched_state state;
 	bool		   is_idle;
 	void		  *stack_base;
@@ -689,6 +691,10 @@ sched_yield(void)
 
 	if (!scheduler_started)
 		return;
+	task = sched_current_task();
+	if (task != NULL)
+		task->yield_count++;
+	perf_counter_inc(PERF_COUNTER_SCHED_YIELD, 1);
 	flags = arch_irq_save();
 	state = sched_state_current();
 	if (state == NULL || !state->idle_ready) {
@@ -719,6 +725,10 @@ sched_block_current(void)
 
 	if (!scheduler_started)
 		return;
+	task = sched_current_task();
+	if (task != NULL)
+		task->block_count++;
+	perf_counter_inc(PERF_COUNTER_SCHED_BLOCK, 1);
 	flags = arch_irq_save();
 	state = sched_state_current();
 	if (state == NULL || !state->idle_ready) {
@@ -955,6 +965,8 @@ task->stack_base = stack;
 	 * transition them to RUNNABLE when they hit a run queue.
 	 */
 	task->state = SCHED_STATE_UNUSED;
+	task->yield_count = 0;
+	task->block_count = 0;
 	task->is_idle = false;
 	task->next = NULL;
 	task->is_user = false;
@@ -2607,6 +2619,30 @@ sched_dump_telemetry(void)
 	}
 }
 
+void
+sched_dump_yielders(void)
+{
+	struct sched_task *iter = task_list_head;
+
+	printk("* sched: per-task yield/block counters\n");
+	while (iter != NULL) {
+		if (iter->state != SCHED_STATE_UNUSED) {
+			printk("  ");
+			printk(iter->name ? iter->name : "(null)");
+			printk(" pid=");
+			sched_print_uint(iter->id);
+			printk(" yields=");
+			sched_print_uint(iter->yield_count);
+			printk(" blocks=");
+			sched_print_uint(iter->block_count);
+			printk(" state=");
+			sched_print_uint((uint64_t)iter->state);
+			printk("\n");
+		}
+		iter = iter->next_global;
+	}
+}
+
 const char *
 sched_current_task_name(void)
 {