Skip to content
Permalink

Comparing changes

Choose two branches to see what’s changed or to start a new pull request. If you need to, you can also or learn more about diff comparisons.

Open a pull request

Create a new pull request by comparing changes across two branches. If you need to, you can also . Learn more about diff comparisons here.
base repository: m-labs/artiq
Failed to load repositories. Confirm that selected base ref is valid, then try again.
Loading
base: 7c2b1155ef6c
Choose a base ref
...
head repository: m-labs/artiq
Failed to load repositories. Confirm that selected head ref is valid, then try again.
Loading
compare: feed91d8b2bb
Choose a head ref
  • 4 commits
  • 6 files changed
  • 1 contributor

Commits on Nov 12, 2016

  1. artiq_devtool: abort if build failed.

    whitequark committed Nov 12, 2016
    Copy the full SHA
    dca3fb5 View commit details
  2. Copy the full SHA
    acc5e53 View commit details
  3. runtime: don't print debug messages to the UART.

    It takes ~4ms to print an empty log line because of how slow
    the UART is. This makes the log timestamps useless for debugging
    performance problems.
    
    After this commit, it takes ~75us to print an empty log line instead,
    which pessimizes test_rpc_timing by less than 2ms with tracing
    enabled.
    whitequark committed Nov 12, 2016
    Copy the full SHA
    3ce1826 View commit details
  4. runtime: buffer RPC send packets.

    This brings mean RPC time from ~45ms to ~2ms.
    
    The cause of the slowness without buffering is, primarily, that lwip
    is severely pessimized by small writes, whether with Nagle on or off.
    (In fact, disabling Nagle makes it function *better* on many small
    writes, which begs the question of what's the point of having Nagle
    there in the first place.) In practical terms, the slowness appears
    only when writing a 4-byte buffer (the synchronization segment);
    writing buffers of other sizes does not trigger the problem.
    
    This all is extremely confusing and the fix is partly palliative,
    but since it seems to work reliably and we're migrating off lwip
    I think it is unwise to spend any more time debugging this.
    whitequark committed Nov 12, 2016
    Copy the full SHA
    feed91d View commit details
12 changes: 8 additions & 4 deletions artiq/frontend/artiq_devtool.py
Original file line number Diff line number Diff line change
@@ -83,10 +83,14 @@ def drain(chan):
for action in args.actions:
if action == "build":
logger.info("Building runtime")
subprocess.call(["python3", "-m", "artiq.gateware.targets.kc705",
"-H", "nist_clock",
"--no-compile-gateware",
"--output-dir", "/tmp/kc705"])
try:
subprocess.check_call(["python3", "-m", "artiq.gateware.targets.kc705",
"-H", "nist_clock",
"--no-compile-gateware",
"--output-dir", "/tmp/kc705"])
except subprocess.CalledProcessError:
logger.error("Build failed")
sys.exit(1)

elif action == "boot":
logger.info("Uploading runtime")
7 changes: 7 additions & 0 deletions artiq/runtime.rs/src/clock.rs
Original file line number Diff line number Diff line change
@@ -12,6 +12,13 @@ pub fn init() {
}
}

pub fn get_us() -> u64 {
unsafe {
csr::timer0::update_value_write(1);
(INIT - csr::timer0::value_read()) / (FREQ / 1_000_000)
}
}

pub fn get_ms() -> u64 {
unsafe {
csr::timer0::update_value_write(1);
2 changes: 1 addition & 1 deletion artiq/runtime.rs/src/lib.rs
Original file line number Diff line number Diff line change
@@ -97,7 +97,7 @@ pub extern "C" fn _Unwind_Resume() -> ! {

#[no_mangle]
pub unsafe extern fn rust_main() {
static mut LOG_BUFFER: [u8; 4096] = [0; 4096];
static mut LOG_BUFFER: [u8; 65536] = [0; 65536];
BufferLogger::new(&mut LOG_BUFFER[..])
.register(move || {
info!("booting ARTIQ...");
14 changes: 9 additions & 5 deletions artiq/runtime.rs/src/logger.rs
Original file line number Diff line number Diff line change
@@ -1,7 +1,8 @@
use core::{mem, ptr};
use core::cell::RefCell;
use log::{self, Log, LogMetadata, LogRecord, LogLevelFilter};
use log::{self, Log, LogLevel, LogMetadata, LogRecord, LogLevelFilter};
use log_buffer::LogBuffer;
use clock;

pub struct BufferLogger {
buffer: RefCell<LogBuffer<&'static mut [u8]>>
@@ -57,10 +58,13 @@ impl Log for BufferLogger {
fn log(&self, record: &LogRecord) {
if self.enabled(record.metadata()) {
use core::fmt::Write;
writeln!(self.buffer.borrow_mut(), "{:>5}({}): {}",
record.level(), record.target(), record.args()).unwrap();
println!("{:>5}({}): {}",
record.level(), record.target(), record.args());
writeln!(self.buffer.borrow_mut(),
"[{:12}us] {:>5}({}): {}",
clock::get_us(), record.level(), record.target(), record.args()).unwrap();
if record.level() <= LogLevel::Info {
println!("[{:12}us] {:>5}({}): {}",
clock::get_us(), record.level(), record.target(), record.args());
}
}
}
}
7 changes: 4 additions & 3 deletions artiq/runtime.rs/src/session.rs
Original file line number Diff line number Diff line change
@@ -114,7 +114,7 @@ fn host_read(stream: &mut TcpStream) -> io::Result<host::Request> {
Ok(request)
}

fn host_write(stream: &mut TcpStream, reply: host::Reply) -> io::Result<()> {
fn host_write(stream: &mut Write, reply: host::Reply) -> io::Result<()> {
trace!("comm->host {:?}", reply);
reply.write_to(stream)
}
@@ -389,8 +389,9 @@ fn process_kern_message(waiter: Waiter,
match stream {
None => unexpected!("unexpected RPC in flash kernel"),
Some(ref mut stream) => {
try!(host_write(stream, host::Reply::RpcRequest { async: async }));
try!(rpc::send_args(&mut BufWriter::new(stream), service, tag, data));
let writer = &mut BufWriter::new(stream);
try!(host_write(writer, host::Reply::RpcRequest { async: async }));
try!(rpc::send_args(writer, service, tag, data));
if !async {
session.kernel_state = KernelState::RpcWait
}
8 changes: 5 additions & 3 deletions artiq/test/coredevice/test_rtio.py
Original file line number Diff line number Diff line change
@@ -450,6 +450,8 @@ class RPCTest(ExperimentCase):
"timings are dependent on CPU load and network conditions")
def test_rpc_timing(self):
self.execute(RPCTiming)
self.assertGreater(self.dataset_mgr.get("rpc_time_mean"), 100*ns)
self.assertLess(self.dataset_mgr.get("rpc_time_mean"), 15*ms)
self.assertLess(self.dataset_mgr.get("rpc_time_stddev"), 2*ms)
rpc_time_mean = self.dataset_mgr.get("rpc_time_mean")
print(rpc_time_mean)
self.assertGreater(rpc_time_mean, 100*ns)
self.assertLess(rpc_time_mean, 2*ms)
self.assertLess(self.dataset_mgr.get("rpc_time_stddev"), 1*ms)