tokio-postgres: buffer sockets to avoid excessive syscalls

[petrosagg]

The current implementation forwards all read requests to the operating system through the socket causing excessive system calls. The effect is magnified when the underlying Socket is wrapped around a TLS implementation.

This commit changes the underlying socket to be read-buffered by default with a buffer size of 16K, following the implementation of the official client.

The effect can be seen from these two strace captures:

Before

Many sub 100 byte reads

[nix-shell:~/tmp/pg-syscall-test]$ strace -f -e recvfrom ./target/debug/pg-syscall-test
strace: Process 1894582 attached
strace: Process 1894583 attached
strace: Process 1894584 attached
strace: Process 1894585 attached
[pid 1894581] recvfrom(9, "S", 1, 0, NULL, NULL) = 1
[pid 1894581] recvfrom(9, 0x55e5e2808463, 5, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
[pid 1894581] recvfrom(9, "\26\3\3\0X", 5, 0, NULL, NULL) = 5
[pid 1894581] recvfrom(9, "\2\0\0T\3\3\317!\255t\345\232a\21\276\35\214\2\36e\270\221\302\242\21\26z\273\214^\7\236"..., 88, 0, NULL, NULL) = 88
[pid 1894581] recvfrom(9, "\24\3\3\0\1", 5, 0, NULL, NULL) = 5
[pid 1894581] recvfrom(9, "\1", 1, 0, NULL, NULL) = 1
[pid 1894581] recvfrom(9, 0x55e5e2808463, 5, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
[pid 1894581] recvfrom(9, "\26\3\3\0\233", 5, 0, NULL, NULL) = 5
[pid 1894581] recvfrom(9, "\2\0\0\227\3\3^\247Y\275)L\27\t\212\21\241\256l\273\375\272\330\256$\0005\326\210\206\215\27"..., 155, 0, NULL, NULL) = 155
[pid 1894581] recvfrom(9, "\27\3\3\0\27", 5, 0, NULL, NULL) = 5
[pid 1894581] recvfrom(9, "5\227C\222\320r9\355\261\270)\22Z\333\345'\0\206\17\241\332\30\355", 23, 0, NULL, NULL) = 23
[pid 1894581] recvfrom(9, "\27\3\3\4\26", 5, 0, NULL, NULL) = 5
[pid 1894581] recvfrom(9, "\203l\266\326\370\372\241\326\325\v.;L1/g0?U^\217\fo\264\245\16\322w\220\311'y"..., 1046, 0, NULL, NULL) = 1046
[pid 1894581] recvfrom(9, "\27\3\3\1\31", 5, 0, NULL, NULL) = 5
[pid 1894581] recvfrom(9, "\377\317dj?\234\0206l4\247H\33\4+\366\321h\273\322#\234\204[\312\251\212\223\274\375\17W"..., 281, 0, NULL, NULL) = 281
[pid 1894581] recvfrom(9, "\27\3\3\0E", 5, 0, NULL, NULL) = 5
[pid 1894581] recvfrom(9, "\242\367q[\356\36i\323\223{|k\342\340\317\300\324+v0O\230\n\353N\227U\212\310Q\312\224"..., 69, 0, NULL, NULL) = 69
[pid 1894581] recvfrom(9, "\27\3\3\0J", 5, 0, NULL, NULL) = 5
[pid 1894581] recvfrom(9, "F\206\33^\0\317\276&{\246B\323k9\312o|\277\237)\334\0017\212\216\6\0v\2615M\267"..., 74, 0, NULL, NULL) = 74
[pid 1894581] recvfrom(9, "\27\3\3\0J", 5, 0, NULL, NULL) = 5
[pid 1894581] recvfrom(9, "\311\330\363|8\354\26\262\344ml(\222\26A\217\254+\253\255\302\260\275\373\300\367'\207I\202\365\310"..., 74, 0, NULL, NULL) = 74
[pid 1894581] recvfrom(9, 0x55e5e2802f03, 5, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
[pid 1894581] recvfrom(9, "\27\3\3\1l", 5, 0, NULL, NULL) = 5
[pid 1894581] recvfrom(9, "\352\347\216\236\236F\334^\310\1-\275\3752\215\344L\335\24iR\24\202\271ZA\23\201\314'N\240"..., 364, 0, NULL, NULL) = 364
[pid 1894585] recvfrom(9, 0x7fc2d0000cf3, 5, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
[pid 1894582] recvfrom(9, "\27\3\3\0L", 5, 0, NULL, NULL) = 5
[pid 1894582] recvfrom(9, "\327,\347\207\336\21Z\221\30%I}\266\321\254\333\222\356&\177\0240\271\370w\325\22V\2269\240>"..., 76, 0, NULL, NULL) = 76
[pid 1894582] recvfrom(9, 0x7fc2e0001173, 5, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
[pid 1894583] recvfrom(9, "\27\3\3\0\320", 5, 0, NULL, NULL) = 5
[pid 1894583] recvfrom(9, "`\215Xl]\264>\222\212\344\33|1\16\214\n\213eD-=\37\203/\261z\362JP7\255B"..., 208, 0, NULL, NULL) = 208
[pid 1894583] recvfrom(9, 0x7fc2d8000cf3, 5, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
got 11 rows

After

16K buffered reads

[nix-shell:~/tmp/pg-syscall-test]$ strace -f -e recvfrom ./target/debug/pg-syscall-test
strace: Process 1894017 attached
strace: Process 1894018 attached
strace: Process 1894019 attached
strace: Process 1894020 attached
[pid 1894016] recvfrom(9, "S", 16384, 0, NULL, NULL) = 1
[pid 1894016] recvfrom(9, 0x558c13b28f00, 16384, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
[pid 1894016] recvfrom(9, "\26\3\3\0X\2\0\0T\3\3\317!\255t\345\232a\21\276\35\214\2\36e\270\221\302\242\21\26z"..., 16384, 0, NULL, NULL) = 99
[pid 1894016] recvfrom(9, 0x558c13b28f00, 16384, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
[pid 1894016] recvfrom(9, "\26\3\3\0\233\2\0\0\227\3\3\247\350\361\250k\230\227\217\253\360:\177>\372\255\4\273\r2\10\351"..., 16384, 0, NULL, NULL) = 1599
[pid 1894016] recvfrom(9, 0x558c13b28f00, 16384, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
[pid 1894016] recvfrom(9, "\27\3\3\0JoF\207:\365S\323kM\247\309\242\2563\25\10\344U\367c}\312l\225\v\255"..., 16384, 0, NULL, NULL) = 527
[pid 1894018] recvfrom(9, 0x558c13b28f00, 16384, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
[pid 1894019] recvfrom(9, "\27\3\3\0LJ\354\216&|X\351\33A\316a\337\206?\314\360Q\200\350\231\365\233\266U\256\277\363"..., 16384, 0, NULL, NULL) = 81
[pid 1894019] recvfrom(9, 0x558c13b28f00, 16384, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
[pid 1894018] recvfrom(9, "\27\3\3\0\3204x\335T\307\374\"\372$\334\2671k\262\331x\2205\10\316\323\2\222\273\207\20\325"..., 16384, 0, NULL, NULL) = 213
[pid 1894018] recvfrom(9, 0x558c13b28f00, 16384, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
got 11 rows

This is the test program that was used to generate these traces:

use openssl::ssl::{SslConnector, SslMethod, SslVerifyMode};
use postgres_openssl::MakeTlsConnector;

#[tokio::main]
async fn main() {
    let mut builder = SslConnector::builder(SslMethod::tls()).unwrap();
    builder.set_verify(SslVerifyMode::NONE);
    let connector = MakeTlsConnector::new(builder.build());

    let (client, connection) = tokio_postgres::connect(
        "host=127.0.0.1 port=5433 user=postgres sslmode=require",
        connector,
    )
    .await
    .unwrap();

    tokio::spawn(connection);

    let rows = client
        .query("SELECT * FROM generate_series(0, 10)", &[])
        .await
        .unwrap();

    println!("got {} rows", rows.len());
}

[sfackler]

It seems like Postgres is creating a bunch of very small TLS frames, which is not great in its own right, but probably something we have to just live with.

Since this issue is specific to TLS, I think it'd make more sense to move this buffering layer into the TLS backend specifically. The protocol decode logic should already be performing large reads, so buffering directly around the socket will just cause extra memcpy traffic in the unencrypted case.

[petrosagg]

If this is done in the TLS backend it would be a breaking change since the associated types here would need to change from TlsStream<S> to TlsStream<BufReader<S>>. Are you ok with this change? To me it sounds like the copies in the unencrypted case are a small price to pay to maintain backwards compatibility but I'm happy to go either way

[sfackler]

The TlsStream there is a type defined within the postgres-openssl crate itself, so that can just have the BufReader added internally without breaking the interface.

[petrosagg]

Oops, you're right. PR updated.

[sfackler]

I think you'll need to tweak a few other lines a bit to add an extra layer of .get_ref() calls, but that looks good otherwise.

[petrosagg]

Hm, are you sure? The buffered stream is not wrapping the pre-existing SSL streams, it's the other way around. The current PR seems to work for me

[sfackler]

It seems like this line should not compile after your change, but I suppose it does! https://github.com/sfackler/rust-postgres/blob/master/postgres-native-tls/src/lib.rs#L170