Another microbenchmark compared to Ruby

[PeterMozesMerl]

A couple months ago I had a benchmark which compared the Ruby pg gem’s, the Go library’s and the rust-postgres crate’s insert performance. The speed was Rust < Go < Ruby, probably because the well-optimized Ruby gem written in C. Now this benchmark runs with almost the same speed as the Ruby version and it runs faster than the Go one.

However, I also had a select benchmark with rust-postgres 0.4. It used to run slightly slower than the Ruby one. (I still have the old binary and I could confirm this). However, the recent version is magnitudes slower. Since I am a beginner with Rust I can’t tell whether this is an upstream issue or not.

The database has ten thousands of records.

extern crate postgres;

use postgres::{Connection, SslMode};

fn main() {
    println!("Hello, world!");

    // I could not figure out how to use the unix_socket with v0.7 (and did’t try hard)
    let conn = Connection::connect("postgres://mage@localhost/xxx", &SslMode::None).unwrap();

    let cycles = 10;

    let query = "select id from users order by id limit 10000";
    let stmt = conn.prepare(query).unwrap();

    let mut bar: i32;

    for cycle in 0..cycles {
        for row in stmt.query(&[]).unwrap() {
            bar = row.get(0);
            println!("Done: {}", bar);
        }
        println!("Cycle: {}", cycle);
    }
}

$ time cargo run --release
...
Done: 10000
Cycle: 9

real    0m21.885s
user    0m18.290s
sys 0m3.544s

Of course the compile time is not counted, I have compiled it already.

The Ruby version:

require 'pg'

conn = PG.connect(dbname: 'xxx', user: 'mage', host: 'localhost')
stmt = conn.prepare('hoi', "select id from users order by id limit 10000") 

0.upto(9) do |cycle|
    results = conn.exec_prepared("hoi")
    results.each do |row|
        puts "Result: #{row['id']}"
    end
    puts "Done: #{cycle}"
end

$ time ruby postgres2.rb
Result: 9999
Result: 10000
Done: 9

real    0m1.232s
user    0m0.783s
sys 0m0.349s

As for the Rust version, displaying the results from 1 to 10000 is superfast. There is, however, a couple of seconds spent between each cycle.

The old binary (which used rust-postgres version 0.4) does’t have this pause between the cycles. (Note that the old binary uses unix_socket but I don’t think that’s the reason).

$ rustc --version
rustc 1.0.0-nightly (27901849e 2015-03-25) (built 2015-03-26)

This is the old version (compiled on Dec 29, 2014).

$ time ./target/postgres2
Done: 10000
Cycle: 100

real    0m15.154s
user    0m13.401s
sys 0m1.489s

The cycles is set to 100, so it would run for 1.5s with 10 cycles.

[sfackler]

Interesting, I will look into this.

[sfackler]

This line appears to be the offender:

rust-postgres/src/message.rs

Line 360 in 7bcb8fb

try!(buf.take(len as u64).read_to_end(&mut data));

Flamegraph (from an unoptimized build): https://sfackler.com/static/flamegraph.svg

[sfackler]

I believe this commit should fix the issue: 9cd413d

I'm seeing ~.66 second runtimes after that change:

Done: 10000
Cycle: 9
0.03user 0.34system 0:00.66elapsed 57%CPU (0avgtext+0avgdata 7824maxresident)k
0inputs+0outputs (0major+2621minor)pagefaults 0swaps

Thanks for pointing this out! What a weird place to find such a huge performance issue. I've published a new release to crates.io with this fix. I'll leave this issue open until you can confirm that everything looks good on your end as well.

[PeterMozesMerl]

I’ve tested on a different machine, the Ruby version runs for 0.82s (avg) and the updated Rust version runs for 0.43s. This is awesome, thank you for the fix. I look forward to using rust-postgres in production.

[sfackler]

Perfect!