[PATCH v2 07/31] gpu: nova-core: distinguish async GSP RPC traffic in debug logs

[John Hubbard]

The receive path logged every message at the transport layer and did not
distinguish events from command replies. Async sends shared the RPC
sequence with waited-for commands, and GSP-initiated events arrived
with that field unset.

Print a distinct debug line for async send, sync send, event, and
command reply. Number async sends and events with driver-local counters,
which wrap rather than trap, since they only number log lines.

IS_ASYNC selects only the send log line. Every command still carries the
next RPC sequence on the wire.

Assisted-by: Cursor:claude-opus-5
Reviewed-by: Timur Tabi <ttabi@xxxxxxxxxx>
Reviewed-by: Zhi Wang <zhiw@xxxxxxxxxx>
Signed-off-by: John Hubbard <jhubbard@xxxxxxxxxx>
---
 drivers/gpu/nova-core/gsp/cmdq.rs             | 111 ++++++++++++++----
 .../gpu/nova-core/gsp/cmdq/continuation.rs    |   1 +
 drivers/gpu/nova-core/gsp/commands.rs         |   2 +
 drivers/gpu/nova-core/gsp/fw.rs               |  19 +++
 4 files changed, 107 insertions(+), 26 deletions(-)

diff --git a/drivers/gpu/nova-core/gsp/cmdq.rs b/drivers/gpu/nova-core/gsp/cmdq.rs
index ac3e6642031a..1eeef2120b6e 100644
--- a/drivers/gpu/nova-core/gsp/cmdq.rs
+++ b/drivers/gpu/nova-core/gsp/cmdq.rs
@@ -87,6 +87,12 @@ pub(crate) trait CommandToGsp {
     /// Function identifying this command to the GSP.
     const FUNCTION: MsgFunction;
 
+    /// Classifies the send-side debug log as an async send.
+    ///
+    /// Default is `false`. Set this only on commands that are sent without waiting for a reply. A
+    /// [`NoReply`] continuation of a waited-for command stays `false`.
+    const IS_ASYNC: bool = false;
+
     /// Type generated by [`CommandToGsp::init`], to be written into the command queue buffer.
     type Command: FromBytes + AsBytes;
 
@@ -528,6 +534,8 @@ pub(crate) fn new(dev: &device::Device<device::Bound>) -> impl PinInit<Self, Err
                     gsp_mem,
                     elem_seq: 0,
                     rpc_seq: 0,
+                    tx_async_seq: 0,
+                    rx_event_seq: 0,
                     poisoned: Cell::new(false),
                 }),
             }))
@@ -672,6 +680,12 @@ struct CmdqInner {
     /// [`CmdqInner::receive_msg`] match that reply to the awaiting command. Advances once per
     /// logical command.
     rpc_seq: u32,
+    /// Debug-log sequence for async sends. Those commands do not wait for a reply, so this
+    /// counter is the number printed in the send log.
+    tx_async_seq: u32,
+    /// Debug-log sequence for GSP-initiated events. The GSP leaves the RPC sequence unset on
+    /// those messages, so the driver numbers them itself.
+    rx_event_seq: u32,
     /// Set once a message with corrupt framing or a bad checksum is seen. Such a message has an
     /// untrusted length, so the queue cannot be advanced past it, and every later receive fails
     /// until the queue is torn down and reset.
@@ -738,13 +752,24 @@ fn send_single_command<M>(&mut self, bar: Bar0<'_>, command: M, rpc_seq: u32) ->
                 dst.contents.1,
             ])));
 
-        dev_dbg!(
-            &self.dev,
-            "GSP RPC: send: seq# {}, function={:?}, length=0x{:x}\n",
-            rpc_seq,
-            M::FUNCTION,
-            dst.header.length(),
-        );
+        if M::IS_ASYNC {
+            dev_dbg!(
+                &self.dev,
+                "GSP RPC: async send: seq# {}, function={:?}, length=0x{:x}\n",
+                self.tx_async_seq,
+                M::FUNCTION,
+                dst.header.length(),
+            );
+            self.tx_async_seq = self.tx_async_seq.wrapping_add(1);
+        } else {
+            dev_dbg!(
+                &self.dev,
+                "GSP RPC: send: seq# {}, function={:?}, length=0x{:x}\n",
+                rpc_seq,
+                M::FUNCTION,
+                dst.header.length(),
+            );
+        }
 
         // All set - update the write pointer and inform the GSP of the new command.
         let elem_count = dst.header.element_count();
@@ -826,14 +851,6 @@ fn wait_for_msg(&self, timeout: Delta) -> Result<GspMessage<'_>> {
             return Err(EIO);
         };
 
-        dev_dbg!(
-            &self.dev,
-            "GSP RPC: receive: seq# {}, function={:?}, length=0x{:x}\n",
-            header.sequence(),
-            header.function(),
-            header.length(),
-        );
-
         let payload_length = header.payload_length();
 
         // Check that the driver read area is large enough for the message.
@@ -877,6 +894,41 @@ fn wait_for_msg(&self, timeout: Delta) -> Result<GspMessage<'_>> {
         })
     }
 
+    /// Writes the classified receive debug line for a decoded GSP message.
+    ///
+    /// Events print [`Self::rx_event_seq`]. Command replies print `seq`. An unrecognized function
+    /// code prints nothing here.
+    fn log_received(&self, function: Result<MsgFunction, u32>, seq: u32, length: usize) {
+        match function {
+            Ok(f) if f.is_event() => {
+                dev_dbg!(
+                    &self.dev,
+                    "GSP RPC: async received: seq# {}, function={:?}, length=0x{:x}\n",
+                    self.rx_event_seq,
+                    f,
+                    length,
+                );
+            }
+            Ok(f) => {
+                dev_dbg!(
+                    &self.dev,
+                    "GSP RPC: response received: seq# {}, function={:?}, length=0x{:x}\n",
+                    seq,
+                    f,
+                    length,
+                );
+            }
+            Err(_) => {}
+        }
+    }
+
+    /// Advances [`Self::rx_event_seq`] after a GSP-initiated event has been consumed.
+    fn advance_rx_event_seq(&mut self, function: Result<MsgFunction, u32>) {
+        if matches!(function, Ok(f) if f.is_event()) {
+            self.rx_event_seq = self.rx_event_seq.wrapping_add(1);
+        }
+    }
+
     /// Receive a message from the GSP.
     ///
     /// The expected message type is given by the `M` generic parameter. With `expected_seq` set,
@@ -910,9 +962,12 @@ fn receive_msg<M: MessageFromGsp>(
         let message = self.wait_for_msg(timeout)?;
         let function = message.header.function();
         let seq = message.header.sequence();
+        let length = message.header.length();
         let func_matches = matches!(function, Ok(f) if f == M::FUNCTION);
         let matched = func_matches && expected_seq.is_none_or(|expected| seq == expected);
 
+        self.log_received(function, seq, length);
+
         // Every path must advance the read pointer past this message, including a failed decode.
         let result = if matched {
             match M::Message::from_bytes_prefix(message.contents.0) {
@@ -938,9 +993,10 @@ fn receive_msg<M: MessageFromGsp>(
         };
 
         // Advance the read pointer past this message.
-        self.gsp_mem.advance_cpu_read_ptr(u32::try_from(
-            message.header.length().div_ceil(GSP_PAGE_SIZE),
-        )?);
+        self.gsp_mem
+            .advance_cpu_read_ptr(u32::try_from(length.div_ceil(GSP_PAGE_SIZE))?);
+
+        self.advance_rx_event_seq(function);
 
         if !matched {
             if func_matches {
@@ -962,8 +1018,8 @@ fn receive_msg<M: MessageFromGsp>(
     /// Routes a GSP message that is not the reply a caller is waiting for.
     ///
     /// GSP-reported errors are logged at error level and unrecognized function codes at warning
-    /// level. Every other known function code is consumed without a log line, because the RPC
-    /// receive trace in [`Self::wait_for_msg`] already records its arrival.
+    /// level. Every other known function code is consumed without a log line, because
+    /// [`Self::log_received`] already records its arrival.
     fn dispatch_event(&self, function: Result<MsgFunction, u32>, seq: u32) {
         match function {
             Ok(MsgFunction::OsErrorLog) => {
@@ -1004,16 +1060,19 @@ fn drain(&mut self) -> Result {
         while !self.gsp_mem.driver_read_area().0.is_empty() {
             // A message is available, so this returns without waiting.
             let msg = self.wait_for_msg(Delta::ZERO)?;
-
-            let pages =
-                u32::try_from(msg.header.length().div_ceil(GSP_PAGE_SIZE)).map_err(|_| {
-                    dev_err!(&self.dev, "GSP drain: message length overflow\n");
-                    EIO
-                })?;
             let function = msg.header.function();
             let seq = msg.header.sequence();
+            let length = msg.header.length();
+
+            self.log_received(function, seq, length);
+
+            let pages = u32::try_from(length.div_ceil(GSP_PAGE_SIZE)).map_err(|_| {
+                dev_err!(&self.dev, "GSP drain: message length overflow\n");
+                EIO
+            })?;
 
             self.gsp_mem.advance_cpu_read_ptr(pages);
+            self.advance_rx_event_seq(function);
             self.dispatch_event(function, seq);
         }
 
diff --git a/drivers/gpu/nova-core/gsp/cmdq/continuation.rs b/drivers/gpu/nova-core/gsp/cmdq/continuation.rs
index 05e904f18097..a606c7be52a7 100644
--- a/drivers/gpu/nova-core/gsp/cmdq/continuation.rs
+++ b/drivers/gpu/nova-core/gsp/cmdq/continuation.rs
@@ -147,6 +147,7 @@ fn new(command: C, payload: KVVec<u8>) -> Self {
 
 impl<C: CommandToGsp> CommandToGsp for SplitCommand<C> {
     const FUNCTION: MsgFunction = C::FUNCTION;
+    const IS_ASYNC: bool = C::IS_ASYNC;
     type Command = C::Command;
     type Reply = C::Reply;
     type InitError = C::InitError;
diff --git a/drivers/gpu/nova-core/gsp/commands.rs b/drivers/gpu/nova-core/gsp/commands.rs
index 61fe93db9e7e..d5575c036eb9 100644
--- a/drivers/gpu/nova-core/gsp/commands.rs
+++ b/drivers/gpu/nova-core/gsp/commands.rs
@@ -52,6 +52,7 @@ pub(crate) fn new(pdev: &'a pci::Device<device::Bound>, chipset: Chipset) -> Sel
 
 impl<'a> CommandToGsp for SetSystemInfo<'a> {
     const FUNCTION: MsgFunction = MsgFunction::GspSetSystemInfo;
+    const IS_ASYNC: bool = true;
     type Command = fw::commands::GspSetSystemInfo;
     type Reply = NoReply;
     type InitError = Error;
@@ -122,6 +123,7 @@ pub(crate) fn new(vgpu_state: VgpuState) -> Result<Self> {
 
 impl CommandToGsp for SetRegistry {
     const FUNCTION: MsgFunction = MsgFunction::SetRegistry;
+    const IS_ASYNC: bool = true;
     type Command = fw::commands::PackedRegistryTable;
     type Reply = NoReply;
     type InitError = Infallible;
diff --git a/drivers/gpu/nova-core/gsp/fw.rs b/drivers/gpu/nova-core/gsp/fw.rs
index d3678f16750a..857d53c77297 100644
--- a/drivers/gpu/nova-core/gsp/fw.rs
+++ b/drivers/gpu/nova-core/gsp/fw.rs
@@ -359,6 +359,25 @@ fn try_from(value: u32) -> Result<MsgFunction> {
     }
 }
 
+impl MsgFunction {
+    /// Returns true if this is a GSP-initiated async event (`NV_VGPU_MSG_EVENT_*`), as opposed to
+    /// a command response (`NV_VGPU_MSG_FUNCTION_*`).
+    pub(crate) fn is_event(&self) -> bool {
+        matches!(
+            self,
+            Self::GspInitDone
+                | Self::GspRunCpuSequencer
+                | Self::PostEvent
+                | Self::RcTriggered
+                | Self::MmuFaultQueued
+                | Self::OsErrorLog
+                | Self::GspPostNoCat
+                | Self::GspLockdownNotice
+                | Self::UcodeLibOsPrint //
+        )
+    }
+}
+
 impl From<MsgFunction> for u32 {
     fn from(value: MsgFunction) -> Self {
         // CAST: `MsgFunction` is `repr(u32)` and can thus be cast losslessly.
-- 
2.55.0