-
Notifications
You must be signed in to change notification settings - Fork 224
Startup kernel runs before DEST#0 is up, resulting in RTIODestinationUnreachable #2791
Description
Summary
Regarding the UART logs while the master Kalsi SoC (re)boots, occasionally both Starting startup kernel... and kernel starting occur before [DEST#0] destination is up. When this happens, correspondingly the startup kernel raises a RTIODestinationUnreachable error. This does not happen every time, sometimes [DEST#0] is up before the startup kernel is run.
I have tried delayed accessing the RTIO hardware on the master, [DEST#0], with a loop predicated on not get_rtio_destination_status(0), as I do with the satellite device, however this does not work. It seems get_rtio_destination_status(0) returns True regardless of if [DEST#0] is actually up.
Minimal Bug Example
from artiq.experiment import *
class StartupKernel(EnvExperiment):
def build(self):
self.setattr_device("core")
self.setattr_device("led1")
@kernel
def run(self):
while not self.core.get_rtio_destination_status(0):
pass
self.core.reset()
self.led1.on()
self.core.wait_until_mu(now_mu())
UART Log with Error
[ 30529.089202s] INFO(runtime::mgmt): rebooting
__________ __ / ___/__ / / / \__ \ / / / / ___/ / / /__/ /___ /____/ /____/_____/ (C) 2020-2022 M-Labs[ 0.019996s] INFO(szl): Simple Zynq Loader starting...
[ 0.025203s] DEBUG(libboard_zynq::clocks::source): Set ARM_PLL to 2000000000 Hz
[ 0.007041s] DEBUG(libboard_zynq::clocks::source): Set IO_PLL to 1000000000 Hz
[ 0.016260s] DEBUG(libboard_zynq::clocks::source): Set DDR_PLL to 1066666666 Hz
[ 0.023610s] DEBUG(libboard_zynq::ddr): DDR 3x/2x clocks: 533333328/355555552
[ 0.030778s] DEBUG(libboard_zynq::ddr): DDR DCI clock: 10062892 Hz (divisors=2*53)
[ 0.042001s] DEBUG(libboard_zynq::sdio): Reset SDIO!
[ 0.046949s] DEBUG(libboard_zynq::sdio): Changing clock frequency to 400000
[ 0.053818s] INFO(szl): Card inserted. Mounting file system.
[ 0.081432s] DEBUG(libboard_zynq::sdio): Changing clock frequency to 25000000
[ 0.088561s] DEBUG(libboard_zynq::sdio::sd_card): Getting bus width
[ 0.097021s] DEBUG(libboard_zynq::sdio::sd_card): 4 bit support
[ 0.102917s] DEBUG(libboard_zynq::sdio::sd_card): Changing bus width
[ 0.111000s] DEBUG(libboard_zynq::sdio): Set block size to 512
[ 0.124023s] DEBUG(libconfig::sd_reader): Partition ID: C
[ 0.130265s] INFO(szl): Loading gateware
[ 0.134592s] DEBUG(libconfig::bootgen): Partition header pointer = C80
[ 0.141243s] DEBUG(libconfig::bootgen): Unencrypted length = C39FE
[ 0.147402s] DEBUG(libconfig::bootgen): Partition start address: B630
[ 0.712985s] DEBUG(libboard_zynq::devc): Invalidate DCache for bitstream buffer
[ 0.726683s] DEBUG(libboard_zynq::devc): Init preload FPGA
[ 0.732147s] DEBUG(libboard_zynq::devc): Toggling PROG_B
[ 0.762595s] DEBUG(libboard_zynq::devc): Waiting for done
[ 0.767971s] DEBUG(libboard_zynq::devc): Init postload FPGA
[ 0.773525s] INFO(szl): Loading runtime
[ 0.779640s] DEBUG(libconfig::bootgen): Partition header pointer = C80
[ 0.786366s] DEBUG(libconfig::bootgen): Unencrypted length = B062
[ 0.792440s] DEBUG(libconfig::bootgen): Unencrypted length = 3DA22
[ 0.798601s] DEBUG(libconfig::bootgen): Partition start address: CF030
[ 0.981850s] INFO(szl): Preparing for runtime execution
[ 0.987404s] INFO(szl): executing payload
[ 0.000067s] INFO(runtime): NAR3/Zynq7000 starting...
[ 0.005242s] INFO(runtime): gateware ident: 8+209eba33;brittonlab-legacy-trap
[ 0.017563s] INFO(libboard_zynq::i2c): PCA9548 detected
[ 0.181486s] INFO(runtime::rtio_clocking): using 100MHz reference to make 125MHz RTIO clock with PLL
[ 0.554641s] INFO(libboard_artiq::si5324): waiting for Si5324 lock...
[ 2.694219s] INFO(libboard_artiq::si5324): ...locked
[ 2.749995s] INFO(runtime::rtio_clocking): SYS CLK switched successfully
[ 2.761967s] INFO(libboard_zynq::i2c): PCA9548 detected
[ 2.799609s] INFO(runtime::comms): network addresses: MAC=fc-0f-e7-07-7b-df IPv4=192.168.1.76 IPv6-LL=fe80::fe0f:e7ff:fe07:7bdf IPv6: no configured address
[ 2.830399s] INFO(libboard_artiq::drtio_routing): routing table: RoutingTable { 0: 0; 1: 1 0; }
[ 2.840643s] INFO(runtime::rtio_mgt): SED spreading disabled by default
[ 2.857097s] INFO(runtime::comms): Loading startup kernel...
[ 2.862855s] INFO(runtime::rtio_mgt::drtio): [LINK#0] link RX became up, pinging
[ 2.870373s] INFO(runtime::comms): Starting startup kernel...
[ 2.876197s] INFO(ksupport::kernel::core1): kernel starting
[ 9.773982s] INFO(runtime::rtio_mgt::drtio): [LINK#0] remote replied after 37 packets
[ 9.807681s] INFO(runtime::rtio_mgt::drtio): [LINK#0] link initialization completed
[ 9.815408s] INFO(runtime::rtio_mgt::drtio): [DEST#0] destination is up
[ 9.822120s] INFO(runtime::rtio_mgt::drtio): [DEST#1] destination is up
[ 9.828809s] INFO(runtime::rtio_mgt::drtio): [DEST#1] buffer space is 128
[ 9.840200s] ERROR(runtime::comms): Uncaught kernel exceptions: [Some(Exception 3 from (Rust function) in libksupport/src/kernel/rtio_csr.rs:90:9, message: RTIO destination unreachable, output, at {0} mu, channel 0x0042:led1)]
[ 9.860266s] INFO(runtime::comms): Startup kernel finished!
[ 9.866079s] INFO(runtime::moninj): received connection
[ 9.871389s] INFO(runtime::comms): Loading idle kernel
[ 9.876665s] INFO(runtime::comms): Running idle kernel
[ 9.881879s] INFO(ksupport::kernel::core1): kernel starting
[ 9.893528s] INFO(ksupport::kernel::api): kernel: Idle kernel proceeding with satellite connection status: True
[ 10.366086s] INFO(libboard_zynq::eth): eth: got Link { speed: S1000, duplex: Full }
[ 15.481185s] INFO(runtime::mgmt): received connection
UART Log of successful startup
[ 936.409714s] INFO(runtime::mgmt): rebooting
__________ __ / ___/__ / / / \__ \ / / / / ___/ / / /__/ /___ /____/ /____/_____/ (C) 2020-2022 M-Labs[ 0.019995s] INFO(szl): Simple Zynq Loader starting...
[ 0.025201s] DEBUG(libboard_zynq::clocks::source): Set ARM_PLL to 2000000000 Hz
[ 0.007040s] DEBUG(libboard_zynq::clocks::source): Set IO_PLL to 1000000000 Hz
[ 0.016260s] DEBUG(libboard_zynq::clocks::source): Set DDR_PLL to 1066666666 Hz
[ 0.023609s] DEBUG(libboard_zynq::ddr): DDR 3x/2x clocks: 533333328/355555552
[ 0.030777s] DEBUG(libboard_zynq::ddr): DDR DCI clock: 10062892 Hz (divisors=2*53)
[ 0.042001s] DEBUG(libboard_zynq::sdio): Reset SDIO!
[ 0.046948s] DEBUG(libboard_zynq::sdio): Changing clock frequency to 400000
[ 0.053895s] INFO(szl): Card inserted. Mounting file system.
[ 0.082015s] DEBUG(libboard_zynq::sdio): Changing clock frequency to 25000000
[ 0.089150s] DEBUG(libboard_zynq::sdio::sd_card): Getting bus width
[ 0.097612s] DEBUG(libboard_zynq::sdio::sd_card): 4 bit support
[ 0.103437s] DEBUG(libboard_zynq::sdio::sd_card): Changing bus width
[ 0.111001s] DEBUG(libboard_zynq::sdio): Set block size to 512
[ 0.124023s] DEBUG(libconfig::sd_reader): Partition ID: C
[ 0.130267s] INFO(szl): Loading gateware
[ 0.134600s] DEBUG(libconfig::bootgen): Partition header pointer = C80
[ 0.141330s] DEBUG(libconfig::bootgen): Unencrypted length = C39FE
[ 0.147410s] DEBUG(libconfig::bootgen): Partition start address: B630
[ 0.713060s] DEBUG(libboard_zynq::devc): Invalidate DCache for bitstream buffer
[ 0.726761s] DEBUG(libboard_zynq::devc): Init preload FPGA
[ 0.732225s] DEBUG(libboard_zynq::devc): Toggling PROG_B
[ 0.762672s] DEBUG(libboard_zynq::devc): Waiting for done
[ 0.768049s] DEBUG(libboard_zynq::devc): Init postload FPGA
[ 0.773603s] INFO(szl): Loading runtime
[ 0.779717s] DEBUG(libconfig::bootgen): Partition header pointer = C80
[ 0.786443s] DEBUG(libconfig::bootgen): Unencrypted length = B062
[ 0.792518s] DEBUG(libconfig::bootgen): Unencrypted length = 3DA22
[ 0.798679s] DEBUG(libconfig::bootgen): Partition start address: CF030
[ 0.981875s] INFO(szl): Preparing for runtime execution
[ 0.987508s] INFO(szl): executing payload
[ 0.000067s] INFO(runtime): NAR3/Zynq7000 starting...
[ 0.005242s] INFO(runtime): gateware ident: 8+209eba33;brittonlab-legacy-trap
[ 0.017645s] INFO(libboard_zynq::i2c): PCA9548 detected
[ 0.181451s] INFO(runtime::rtio_clocking): using 100MHz reference to make 125MHz RTIO clock with PLL
[ 0.554617s] INFO(libboard_artiq::si5324): waiting for Si5324 lock...
[ 2.705063s] INFO(libboard_artiq::si5324): ...locked
[ 2.760995s] INFO(runtime::rtio_clocking): SYS CLK switched successfully
[ 2.772961s] INFO(libboard_zynq::i2c): PCA9548 detected
[ 2.810599s] INFO(runtime::comms): network addresses: MAC=fc-0f-e7-07-7b-df IPv4=192.168.1.76 IPv6-LL=fe80::fe0f:e7ff:fe07:7bdf IPv6: no configured address
[ 2.841398s] INFO(libboard_artiq::drtio_routing): routing table: RoutingTable { 0: 0; 1: 1 0; }
[ 2.851639s] INFO(runtime::rtio_mgt): SED spreading disabled by default
[ 2.865686s] INFO(runtime::comms): Loading startup kernel...
[ 2.871443s] INFO(runtime::rtio_mgt::drtio): [DEST#0] destination is up
[ 2.878170s] INFO(runtime::comms): Starting startup kernel...
[ 2.883993s] INFO(ksupport::kernel::core1): kernel starting
[ 2.889770s] INFO(ksupport::kernel::core1): kernel finished
[ 2.895418s] INFO(runtime::comms): Startup kernel finished!
[ 2.901165s] INFO(runtime::comms): Loading idle kernel
[ 2.906439s] INFO(runtime::comms): Running idle kernel
[ 2.911648s] INFO(ksupport::kernel::core1): kernel starting
[ 2.919005s] INFO(ksupport::kernel::api): kernel: Idle kernel proceeding with satellite connection status: False
[ 3.078995s] INFO(runtime::rtio_mgt::drtio): [LINK#0] link RX became up, pinging
[ 6.901088s] INFO(libboard_zynq::eth): eth: got Link { speed: S1000, duplex: Full }
[ 7.745985s] INFO(runtime::rtio_mgt::drtio): [LINK#0] remote replied after 26 packets
[ 7.753982s] INFO(runtime::moninj): received connection
[ 7.781174s] INFO(runtime::rtio_mgt::drtio): [LINK#0] link initialization completed
[ 7.788939s] INFO(runtime::rtio_mgt::drtio): [DEST#1] destination is up
[ 7.795624s] INFO(runtime::rtio_mgt::drtio): [DEST#1] buffer space is 128
[ 8.007909s] INFO(runtime::mgmt): received connection
System
- Operating System:
Ubuntu 22.04.5 LTS - Hardware involved: both master & satellite are Kasli SoC v1.1.1
- ARTIQ version:
ARTIQ v8.9011+18813c6 - Master gateware:
gateware ident: 8+209eba33;brittonlab-legacy-trap - Satellite gateware:
gateware ident 8+209eba33;brittonlab-shared-DRTIO