M-Labs
/
artiq-zynq
10
1
Fork 19
Code Issues 13 Pull Requests Releases Wiki Activity

running kernel in a loop freezes #40

New Issue
Closed
opened 2020-07-07 16:58:11 +08:00 by sb10q · 14 comments
sb10q commented 2020-07-07 16:58:11 +08:00
Owner
Copy Link
from artiq.experiment import *

class Repeat(EnvExperiment):
    def build(self):
        self.setattr_device("core")

    def run(self):
        for _ in range(100):
            print("A")
            self.dummy_kernel()
            print("B")

    @kernel
    def dummy_kernel(self):
        pass

This prints:

> artiq_run repeat.py                                                                                                                                      artiq-zynq-env 
A
B
A
B
A
B
A
B
A
B
A
B
A
B
A
B
A
B
A

...and does not complete

Nothing suspicious in the Zynq log.

``` from artiq.experiment import * class Repeat(EnvExperiment): def build(self): self.setattr_device("core") def run(self): for _ in range(100): print("A") self.dummy_kernel() print("B") @kernel def dummy_kernel(self): pass ``` This prints: ```text > artiq_run repeat.py artiq-zynq-env A B A B A B A B A B A B A B A B A B A ``` ...and does not complete Nothing suspicious in the Zynq log.
sb10q commented 2020-07-07 16:59:39 +08:00
Author
Owner
Copy Link

Note that the Zynq does not crash from this; interrupting the experiment with Ctrl-C and running it again without rebooting the Zynq will give the same result.

Note that the Zynq does not crash from this; interrupting the experiment with Ctrl-C and running it again without rebooting the Zynq will give the same result.
pca006132 commented 2020-07-07 17:09:10 +08:00
Contributor
Copy Link

I've added some logs:

[    15.426989s] DEBUG(runtime::kernel): kernel loaded
[    15.432699s]  INFO(runtime::kernel): kernel starting
[    15.437648s] TRACE(runtime::rpc): send<1>(None)->None
[    15.442692s]  INFO(runtime::kernel): kernel finished
[    15.498375s]  INFO(runtime::comms): Trying to load the kernel
[    15.510266s]  INFO(runtime::comms): core1 restart
[    15.515223s] DEBUG(runtime::kernel): Core1 started
[    15.520003s] DEBUG(runtime::kernel): FPU enabled on Core1
[    15.526446s] DEBUG(dyld): ELF target: 69656 bytes, align to 10000, allocated at 00170000
[    15.534517s] TRACE(dyld): Program header: 00000368+00000010 to 00170000
[    15.541113s] TRACE(dyld): Program header: 00000000+00000378 to 00170000
[    15.547724s] TRACE(dyld): Program header: 00000F80+00000094 to 00170000
[    15.554326s] TRACE(dyld): Program header: 00000F80+00000080 to 00170000
[    15.560921s] TRACE(dyld): Program header: 00000000+00000000 to 00170000
[    15.567517s] TRACE(dyld): Program header: 00000F80+00000080 to 00170000
[    15.574119s] DEBUG(dyld): Relocating 0 rela, 0 rel, 16 pltrel
[    15.579868s] TRACE(dyld::reloc): resolved symbol "__artiq_personality"
[    15.586387s] TRACE(dyld::reloc): resolved symbol "rpc_send_async"
[    15.592474s] DEBUG(runtime::kernel): kernel loaded
[    15.597912s]  INFO(runtime::kernel): kernel starting
[    15.602863s] TRACE(runtime::rpc): send<1>(None)->None
[    15.607907s]  INFO(runtime::kernel): kernel finished

It seems that it the comms module did not receive a LoadKernel request here...
Interrupting the experiment with Ctrl-C and re-run again did not give any log related to shutting down connection etc.

I've added some logs: ``` [ 15.426989s] DEBUG(runtime::kernel): kernel loaded [ 15.432699s] INFO(runtime::kernel): kernel starting [ 15.437648s] TRACE(runtime::rpc): send<1>(None)->None [ 15.442692s] INFO(runtime::kernel): kernel finished [ 15.498375s] INFO(runtime::comms): Trying to load the kernel [ 15.510266s] INFO(runtime::comms): core1 restart [ 15.515223s] DEBUG(runtime::kernel): Core1 started [ 15.520003s] DEBUG(runtime::kernel): FPU enabled on Core1 [ 15.526446s] DEBUG(dyld): ELF target: 69656 bytes, align to 10000, allocated at 00170000 [ 15.534517s] TRACE(dyld): Program header: 00000368+00000010 to 00170000 [ 15.541113s] TRACE(dyld): Program header: 00000000+00000378 to 00170000 [ 15.547724s] TRACE(dyld): Program header: 00000F80+00000094 to 00170000 [ 15.554326s] TRACE(dyld): Program header: 00000F80+00000080 to 00170000 [ 15.560921s] TRACE(dyld): Program header: 00000000+00000000 to 00170000 [ 15.567517s] TRACE(dyld): Program header: 00000F80+00000080 to 00170000 [ 15.574119s] DEBUG(dyld): Relocating 0 rela, 0 rel, 16 pltrel [ 15.579868s] TRACE(dyld::reloc): resolved symbol "__artiq_personality" [ 15.586387s] TRACE(dyld::reloc): resolved symbol "rpc_send_async" [ 15.592474s] DEBUG(runtime::kernel): kernel loaded [ 15.597912s] INFO(runtime::kernel): kernel starting [ 15.602863s] TRACE(runtime::rpc): send<1>(None)->None [ 15.607907s] INFO(runtime::kernel): kernel finished ``` It seems that it the comms module did not receive a LoadKernel request here... Interrupting the experiment with Ctrl-C and re-run again did not give any log related to shutting down connection etc.
sb10q commented 2020-07-14 16:45:22 +08:00
Author
Owner
Copy Link

Looks like a smoltcp/async problem. When this occurs, in the proto_async.rs expect function, stream.recv keeps calling the closure with buf == [90, 90, 90] even though the client had sent much more data (as seen on wireshark trace).

I had removed the RPC code when testing this (as RPCs tends to cause corruption and insane behavior) so this is probably an unrelated and regular bug.

Looks like a smoltcp/async problem. When this occurs, in the ``proto_async.rs`` ``expect`` function, ``stream.recv`` keeps calling the closure with ``buf == [90, 90, 90]`` even though the client had sent much more data (as seen on wireshark trace). I had removed the RPC code when testing this (as RPCs tends to cause corruption and insane behavior) so this is probably an unrelated and regular bug.
astro was assigned by sb10q 2020-07-14 16:47:22 +08:00
sb10q commented 2020-07-15 17:56:06 +08:00
Author
Owner
Copy Link

Deleted the kernel loading and execution code completely from core1, behavior is exactly the same. This continues to look like a Bohrbug.

Deleted the kernel loading and execution code completely from core1, behavior is exactly the same. This continues to look like a Bohrbug.
sb10q added the
priority:critical
 label 2020-07-15 18:04:36 +08:00
astro commented 2020-07-16 04:24:41 +08:00
Contributor
Copy Link

Seeing this repeatedly after the kernel gets stuck when enabling feature log for smoltcp:

[   385.035827s] DEBUG(smoltcp::socket::tcp): #3:192.168.1.52:1381:192.168.1.1:44132: received a keep-alive or window probe packet, will send an ACK
[   385.048804s] DEBUG(smoltcp::socket::tcp): sending sACK option with current assembler ranges
Seeing this repeatedly after the kernel gets stuck when enabling feature `log` for smoltcp: ``` [ 385.035827s] DEBUG(smoltcp::socket::tcp): #3:192.168.1.52:1381:192.168.1.1:44132: received a keep-alive or window probe packet, will send an ACK [ 385.048804s] DEBUG(smoltcp::socket::tcp): sending sACK option with current assembler ranges ```
astro commented 2020-07-16 07:08:17 +08:00
Contributor
Copy Link

Two more observations:

  • Outgoing TCP packets (both replies + egress) have window_len: 0 when the connection gets stuck
  • Increasing the TcpSocket RX buffer size is a workaround
Two more observations: - Outgoing TCP packets (both replies + egress) have `window_len: 0` when the connection gets stuck - Increasing the TcpSocket RX buffer size is a workaround
astro commented 2020-07-18 08:29:35 +08:00
Contributor
Copy Link

The issue happens when TCP RX packets were fragmented in an unfortunate way. We may only get a tiny fragment of the RX buffer in a recv() callback.

I am considering a revision of our recv() API and how we use it. Returning Poll::Pending from the callback is not useful due to this behavior.

To demonstate, this resolves the problem for me:

diff --git a/src/runtime/src/proto_async.rs b/src/runtime/src/proto_async.rs
index 953c6f2..46250a8 100644
--- a/src/runtime/src/proto_async.rs
+++ b/src/runtime/src/proto_async.rs
@@ -10,18 +10,27 @@ use libasync::smoltcp::TcpStream;
 type Result<T> = core::result::Result<T, smoltcp::Error>;
 
 pub async fn expect(stream: &TcpStream, pattern: &[u8]) -> Result<bool> {
-    stream.recv(|buf| {
-        for (i, b) in buf.iter().enumerate() {
-            if *b == pattern[i] {
-                if i + 1 == pattern.len() {
-                    return Poll::Ready((i + 1, Ok(true)));
+    let mut offset = 0;
+    while offset < pattern.len() {
+        let new_offset = stream.recv(|buf| {
+            let len = buf.len().min(pattern.len() - offset);
+            for (i, b) in buf[..len].iter().enumerate() {
+                if *b != pattern[offset + i] {
+                    // mismatch
+                    return Poll::Ready((i + 1, None));
                 }
-            } else {
-                return Poll::Ready((i + 1, Ok(false)));
             }
+            Poll::Ready((len, Some(offset + len)))
+        }).await?;
+        match new_offset {
+            Some(new_offset) =>
+                offset = new_offset,
+            None =>
+                // mismatch
+                return Ok(false),
         }
-        Poll::Pending
-    }).await?
+    }
+    Ok(true)
 }
The issue happens when TCP RX packets were fragmented in an unfortunate way. We may only get a tiny fragment of the RX buffer in a `recv()` callback. I am considering a revision of our `recv()` API and how we use it. Returning `Poll::Pending` from the callback is not useful due to this behavior. To demonstate, this resolves the problem for me: ```patch diff --git a/src/runtime/src/proto_async.rs b/src/runtime/src/proto_async.rs index 953c6f2..46250a8 100644 --- a/src/runtime/src/proto_async.rs +++ b/src/runtime/src/proto_async.rs @@ -10,18 +10,27 @@ use libasync::smoltcp::TcpStream; type Result<T> = core::result::Result<T, smoltcp::Error>; pub async fn expect(stream: &TcpStream, pattern: &[u8]) -> Result<bool> { - stream.recv(|buf| { - for (i, b) in buf.iter().enumerate() { - if *b == pattern[i] { - if i + 1 == pattern.len() { - return Poll::Ready((i + 1, Ok(true))); + let mut offset = 0; + while offset < pattern.len() { + let new_offset = stream.recv(|buf| { + let len = buf.len().min(pattern.len() - offset); + for (i, b) in buf[..len].iter().enumerate() { + if *b != pattern[offset + i] { + // mismatch + return Poll::Ready((i + 1, None)); } - } else { - return Poll::Ready((i + 1, Ok(false))); } + Poll::Ready((len, Some(offset + len))) + }).await?; + match new_offset { + Some(new_offset) => + offset = new_offset, + None => + // mismatch + return Ok(false), } - Poll::Pending - }).await? + } + Ok(true) } ```
astro commented 2020-07-18 10:16:41 +08:00
Contributor
Copy Link

On the other hand, let's have another look if smoltcp shouldn't be able to merge these fragments...

On the other hand, let's have another look if smoltcp shouldn't be able to merge these fragments...
dpn commented 2020-07-18 23:34:32 +08:00
Collaborator
Copy Link

Ah, doesn't TcpSocket::recv() only return a single contiguous slice from the ring buffer? That is, don't you need either keep a buffer in TcpStream to make the TcpStream::recv API work, or change clients to be able to accept a list of buffers?

Ah, doesn't `TcpSocket::recv()` only return a single contiguous slice from the ring buffer? That is, don't you need either keep a buffer in `TcpStream` to make the `TcpStream::recv` API work, or change clients to be able to accept a list of buffers?
dpn commented 2020-07-18 23:41:28 +08:00
Collaborator
Copy Link

In other words, seems like you'll always need to expect smoltcp's recv() to return incomplete data.

See e.g. https://github.com/smoltcp-rs/smoltcp/issues/359 for a discussion about changing the buffer data structure to avoid the extra copy in client code.

In other words, seems like you'll always need to expect smoltcp's recv() to return incomplete data. See e.g. https://github.com/smoltcp-rs/smoltcp/issues/359 for a discussion about changing the buffer data structure to avoid the extra copy in client code.
dpn commented 2020-07-19 00:31:04 +08:00
Collaborator
Copy Link

@astro: Do you think you'll get around to finishing this soon? If not, I can have a look.

@astro: Do you think you'll get around to finishing this soon? If not, I can have a look.
sb10q commented 2020-07-19 14:00:53 +08:00
Author
Owner
Copy Link

One way of solving this would be to mandate that consumers take at least one byte when there's any data available. It shouldn't be too hard to fix the runtime's socket I/O functions to ensure that AFAICT.

One way of solving this would be to mandate that consumers take at least one byte when there's any data available. It shouldn't be too hard to fix the runtime's socket I/O functions to ensure that AFAICT.
sb10q commented 2020-07-19 16:18:46 +08:00
Author
Owner
Copy Link

@astro @pca006132 @dpn Thanks for finding out the root cause of the problem. I fixed it, now I can run 1000 iterations of a kernel in a loop without problem. If you think you have a better solution let me know.

@astro @pca006132 @dpn Thanks for finding out the root cause of the problem. I fixed it, now I can run 1000 iterations of a kernel in a loop without problem. If you think you have a better solution let me know.
sb10q closed this issue 2020-07-19 16:18:50 +08:00
astro commented 2020-07-21 00:09:47 +08:00
Contributor
Copy Link

Even if smoltcp was able to merge subsequent TCP segegments, we may still end up receiving at the tail end of the ring buffer. The current approach seems best.

Even if smoltcp was able to merge subsequent TCP segegments, we may still end up receiving at the tail end of the ring buffer. The current approach seems best.
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
master
release-7
release-8
release-6
Labels
Clear labels   
priority:critical

   
priority:high

   
priority:low

   
priority:medium
No Label
priority:critical
priority:high
priority:low
priority:medium
Milestone
Clear milestone
No items
No Milestone
Assignees
Clear assignees
No Assignees
4 Participants
Notifications
Due Date
The due date is invalid or out of range. Please use the format 'yyyy-mm-dd'.

No due date set.

Dependencies

No dependencies set.

Reference: M-Labs/artiq-zynq#40
No description provided.
Delete Branch "%!s(<nil>)"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?