Skip to content

use TCP keepalive for CockroachDB connections - #11083

Open
davepacheco wants to merge 2 commits into
mainfrom
dap/crdb-keepalive
Open

use TCP keepalive for CockroachDB connections#11083
davepacheco wants to merge 2 commits into
mainfrom
dap/crdb-keepalive

Conversation

@davepacheco

Copy link
Copy Markdown
Collaborator

Fixes #10668. The tunables here configure connections to be closed in about 60 seconds.

@davepacheco

Copy link
Copy Markdown
Collaborator Author

Unfortunately, there's no great way to automatically test this. Diesel doesn't expose the fd it uses for its connections, so there's no way for the program itself to inspect the socket and see its TCP keepalive settings. The only way I can think to do this is some platform-specific and either complex or unstable way to enumerate all fds to find ours (e.g., parse pfiles output or create libproc bindings, which seems like overkill here).

What I did do is verify this by hand as follows. First, I ran:

$ cargo xtask omicron-dev run-all
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.44s
     Running `target/debug/xtask omicron-dev run-all`
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 1.05s
     Running `target/debug/omicron-dev run-all`
omicron-dev: setting up all services ... 
log file: /dangerzone/dap_tmp/omicron-dev-omicron-dev.3646.0.log
note: configured to log to "/dangerzone/dap_tmp/omicron-dev-omicron-dev.3646.0.log"
DB URL: postgresql://root@[::1]:55908/omicron?sslmode=disable
DB address: [::1]:55908
log file: /dangerzone/dap_tmp/omicron-dev-omicron-dev.3646.2.log
note: configured to log to "/dangerzone/dap_tmp/omicron-dev-omicron-dev.3646.2.log"
Dendrite address: [::1]:60635 (dpd backend: [::1]:35236)
omicron-dev: Adding disks to first sled agent
omicron-dev: services are running.
omicron-dev: nexus external API:     127.0.0.1:12220
omicron-dev: nexus internal API:     [::1]:12221
omicron-dev: nexus lockstep API:     [::1]:12232
omicron-dev: sled agent API:         http://[::1]:33237
omicron-dev: cockroachdb pid:        3656
omicron-dev: cockroachdb URL:        postgresql://root@[::1]:55908/omicron?sslmode=disable
omicron-dev: cockroachdb directory:  /dangerzone/dap_tmp/.tmp45HIQu
omicron-dev: clickhouse native addr: [::1]:57381
omicron-dev: clickhouse http addr:   [::1]:34292
omicron-dev: internal DNS HTTP:      http://[::1]:42117
omicron-dev: internal DNS:           [::1]:60938
omicron-dev: external DNS name:      oxide-dev.test
omicron-dev: external DNS HTTP:      http://[::1]:53530
omicron-dev: external DNS:           [::1]:37749
omicron-dev:   e.g. `dig @::1 -p 37749 test-suite-silo.sys.oxide-dev.test`
omicron-dev: management gateway:     http://[::1]:38564 (switch0)
omicron-dev: silo name:              test-suite-silo
omicron-dev: privileged user name:   test-privileged
omicron-dev: privileged password:    oxide

Note that CockroachDB is listening on port 55908. I use this below.

I found the process with ptree:

$ ptree
...
  27521  /usr/libexec/amd64/sshd-session -R
    27523  /usr/libexec/amd64/sshd-session -R
      27524  -bash
        3646   target/debug/omicron-dev run-all
          3656   cockroach start-single-node --insecure --http-addr=:0 --store=path=
          3659   clickhouse server --config-file /dangerzone/dap_tmp/omicron-dev-omi
          3661   dpd run --listen-addresses [::1]:0 --enable-rpw --nexus-address [::
          3662   mgd run --admin-addr ::1 --admin-port 0 --admin-port-file /dangerzo
          3663   ddmd --admin-addr ::1 --admin-port 0 --admin-port-file /dangerzone/
...

then I used mdb -k and located fds representing connections to the CockroachDB port:

dap@ivanova ~ $ pfexec mdb -k
Loading modules: [ unix genunix specfs dtrace mac cpu.generic uppc apix scsi_vhci zfs sata ip hook neti sockfs arp usba xhci smbios stmf stmf_sbd mm lofs crypto random cpc ufs logindmux nsmb ptm smbsrv klmmod nfs vmm ]
> 0t3646::pid2proc | ::pfiles ! awk '$NF == 55908'
  19 SOCK fffffe82779a1340 socket: AF_INET6 0:1:: 47544 remote: AF_INET6 ::1 55908 
  20 SOCK fffffe82aae02980 socket: AF_INET6 0:1:: 52381 remote: AF_INET6 ::1 55908 
  21 SOCK fffffe8294ef3180 socket: AF_INET6 0:1:: 47680 remote: AF_INET6 ::1 55908 
  22 SOCK fffffe828e218700 socket: AF_INET6 0:1:: 60775 remote: AF_INET6 ::1 55908 
  23 SOCK fffffe829b308d00 socket: AF_INET6 0:1:: 37083 remote: AF_INET6 ::1 55908 
  24 SOCK fffffe8350271340 socket: AF_INET6 0:1:: 46736 remote: AF_INET6 ::1 55908 
  25 SOCK fffffe82aae3e240 socket: AF_INET6 0:1:: 44172 remote: AF_INET6 ::1 55908 
  26 SOCK fffffe828cf35e00 socket: AF_INET6 0:1:: 61028 remote: AF_INET6 ::1 55908 
  67 SOCK fffffe82aca1da40 socket: AF_INET6 0:1:: 64422 remote: AF_INET6 ::1 55908 
  70 SOCK fffffe84001a0480 socket: AF_INET6 0:1:: 37756 remote: AF_INET6 ::1 55908 
  71 SOCK fffffe82759b0640 socket: AF_INET6 0:1:: 42783 remote: AF_INET6 ::1 55908 
  74 SOCK fffffe82928b1400 socket: AF_INET6 0:1:: 49141 remote: AF_INET6 ::1 55908 
  75 SOCK fffffe82b46b4e80 socket: AF_INET6 0:1:: 63808 remote: AF_INET6 ::1 55908 
  77 SOCK fffffe829ad3e880 socket: AF_INET6 0:1:: 37530 remote: AF_INET6 ::1 55908 
  78 SOCK fffffe829b19a980 socket: AF_INET6 0:1:: 56773 remote: AF_INET6 ::1 55908 
  82 SOCK fffffe827ac82500 socket: AF_INET6 0:1:: 33897 remote: AF_INET6 ::1 55908 

I put the vnodes (the addresses in column 3) into a file:

> 0t3646::pid2proc | ::pfiles ! awk '$NF == 55908{ print $3 }' > sockets.txt

and piped that back into mdb with ::cat. I dumped out each one's TCP keepalive settings using the same pointer-chasing that I did in #10668. I piped this to sort | uniq -c on the expectation that they'd all have the same settings and I could just check them once:

> ::cat sockets.txt | ::print vnode_t v_data | ::print -t struct sonode so_proto_handle | ::print conn_t conn_proto_priv.cp_tcp[] ! grep tcp_ka | sort | uniq -c | sort -n
  16     conn_proto_priv.cp_tcp->tcp_ka_abort_thres = 0x7530
  16     conn_proto_priv.cp_tcp->tcp_ka_cnt = 0x6
  16     conn_proto_priv.cp_tcp->tcp_ka_interval = 0x7530
  16     conn_proto_priv.cp_tcp->tcp_ka_last_intrvl = 0
  16     conn_proto_priv.cp_tcp->tcp_ka_rinterval = 0x1388
  16     conn_proto_priv.cp_tcp->tcp_ka_tid = 0

Let's see those values in decimal:

> 0x7530=E
                30000                
> 0x1388=E
                5000    

Finally, what are those fields?

https://github.com/illumos/illumos-gate/blob/7d32109ee973334ac380edd5174e9ef912c7731d/usr/src/uts/common/inet/tcp.h#L349-L360

and from tcp_opt_get, we can see that tcp_ka_interval is the same as the widely-known TCP_KEEPIDLE, but in milliseconds:
https://github.com/illumos/illumos-gate/blob/7d32109ee973334ac380edd5174e9ef912c7731d/usr/src/uts/common/inet/tcp/tcp_opt_data.c#L431-L437

and per tcp(4p):

       TCP_KEEPIDLE      This option, like TCP_KEEPALIVE_THRESHOLD,
                         determines the interval for sending the first
                         probe, except that the option value is an
                         unsigned integer in seconds.  It is provided
                         primarily for compatibility with other Unix
                         flavors.

So:

  • The initial probe is sent after 30 seconds
  • Subsequent probes are sent every 5 seconds
  • The connection is terminated if the system doesn't hear back 30 seconds after sending the initial probe, for a total of 60 seconds

@davepacheco

Copy link
Copy Markdown
Collaborator Author

For completeness, I did the same test without my change and found:

> 0t10437::pid2proc | ::pfiles ! awk '$NF == 57682 { print $3}' > sockets2.txt
> ::cat sockets2.txt | ::print vnode_t v_data | ::print -t struct sonode so_proto_handle | ::print conn_t conn_proto_priv.cp_tcp[] ! grep tcp_ka | sort | uniq -c | sort -n
  16     conn_proto_priv.cp_tcp->tcp_ka_abort_thres = 0x75300
  16     conn_proto_priv.cp_tcp->tcp_ka_cnt = 0
  16     conn_proto_priv.cp_tcp->tcp_ka_interval = 0x6ddd00
  16     conn_proto_priv.cp_tcp->tcp_ka_last_intrvl = 0
  16     conn_proto_priv.cp_tcp->tcp_ka_rinterval = 0
  16     conn_proto_priv.cp_tcp->tcp_ka_tid = 0
> 0x6ddd00=E
                7200000              
> 0x75300=E
                480000               

As expected: without this, the first packet is not sent for 7200 seconds, or two hours. Then it's another 8 minutes before the connection is terminated.

@rmustacc rmustacc left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I spent some time chasing down that these ultimately are libpq settings and the semantics make sense and match the bits you found in the kernel. It may make sense to try and use ipd or similar to drop traffic so we can see that the timeout actually happens. I assume the rest of the stack from diesel through bb8 deal and handle with what I assume is eventually a POLLHUP/POLLERR on the socket.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Nexus handoff hung on stuck database connections

2 participants