Track transaction time

.github/workflows/build-and-push.yaml

@@ -23,17 +23,14 @@ jobs:
 
     steps:
       - name: Checkout Repository
-        uses: actions/checkout@v4
-
-      - name: Set up QEMU
-        uses: docker/setup-qemu-action@v3
+        uses: actions/checkout@v3
 
       - name: Set up Docker Buildx
-        uses: docker/setup-buildx-action@v3
+        uses: docker/setup-buildx-action@v2
 
       - name: Determine tags
         id: metadata
-        uses: docker/metadata-action@v5
+        uses: docker/metadata-action@v4
         with:
           images: ${{ env.registry }}/${{ env.image-name }}
           tags: |
@@ -45,18 +42,15 @@ jobs:
             type=raw,value=latest,enable={{ is_default_branch }}
 
       - name: Log in to the Container registry
-        uses: docker/login-action@v3
+        uses: docker/login-action@v2.1.0
         with:
           registry: ${{ env.registry }}
           username: ${{ github.actor }}
           password: ${{ secrets.GITHUB_TOKEN }}
 
       - name: Build and push ${{ env.image-name }}
-        uses: docker/build-push-action@v6
+        uses: docker/build-push-action@v3
         with:
-          context: .
-          platforms: linux/amd64,linux/arm64
-          provenance: false
           push: true
           tags: ${{ steps.metadata.outputs.tags }}
           labels: ${{ steps.metadata.outputs.labels }}

Cargo.lock

@@ -146,12 +146,6 @@ dependencies = [
  "syn 2.0.26",
 ]
 
-[[package]]
-name = "atomic-waker"
-version = "1.1.2"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "1505bd5d3d116872e7271a6d4e16d81d0c8570876c8de68093a09ac269d8aac0"
-
 [[package]]
 name = "atomic_enum"
 version = "0.2.0"
@@ -548,23 +542,29 @@ checksum = "b6c80984affa11d98d1b88b66ac8853f143217b399d3c74116778ff8fdb4ed2e"
 
 [[package]]
 name = "h2"
-version = "0.4.6"
+version = "0.3.20"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "524e8ac6999421f49a846c2d4411f337e53497d8ec55d67753beffa43c5d9205"
+checksum = "97ec8491ebaf99c8eaa73058b045fe58073cd6be7f596ac993ced0b0a0c01049"
 dependencies = [
- "atomic-waker",
  "bytes",
  "fnv",
  "futures-core",
  "futures-sink",
+ "futures-util",
  "http",
- "indexmap",
+ "indexmap 1.9.3",
  "slab",
  "tokio",
  "tokio-util",
  "tracing",
 ]
 
+[[package]]
+name = "hashbrown"
+version = "0.12.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8a9ee70c43aaf417c914396645a0fa852624801b24ebb7ae78fe8272889ac888"
+
 [[package]]
 name = "hashbrown"
 version = "0.14.0"
@@ -609,9 +609,9 @@ dependencies = [
 
 [[package]]
 name = "http"
-version = "1.1.0"
+version = "0.2.9"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "21b9ddb458710bc376481b842f5da65cdf31522de232c1ca8146abce2a358258"
+checksum = "bd6effc99afb63425aff9b05836f029929e345a6148a14b7ecd5ab67af944482"
 dependencies = [
  "bytes",
  "fnv",
@@ -620,24 +620,12 @@ dependencies = [
 
 [[package]]
 name = "http-body"
-version = "1.0.1"
+version = "0.4.5"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "1efedce1fb8e6913f23e0c92de8e62cd5b772a67e7b3946df930a62566c93184"
+checksum = "d5f38f16d184e36f2408a55281cd658ecbd3ca05cce6d6510a176eca393e26d1"
 dependencies = [
  "bytes",
  "http",
-]
-
-[[package]]
-name = "http-body-util"
-version = "0.1.2"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "793429d76616a256bcb62c2a2ec2bed781c8307e797e2598c50010f2bee2544f"
-dependencies = [
- "bytes",
- "futures-util",
- "http",
- "http-body",
  "pin-project-lite",
 ]
 
@@ -655,12 +643,13 @@ checksum = "c4a1e36c821dbe04574f602848a19f742f4fb3c98d40449f11bcad18d6b17421"
 
 [[package]]
 name = "hyper"
-version = "1.4.1"
+version = "0.14.27"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "50dfd22e0e76d0f662d429a5f80fcaf3855009297eab6a0a9f8543834744ba05"
+checksum = "ffb1cfd654a8219eaef89881fdb3bb3b1cdc5fa75ded05d6933b2b382e395468"
 dependencies = [
  "bytes",
  "futures-channel",
+ "futures-core",
  "futures-util",
  "h2",
  "http",
@@ -669,26 +658,13 @@ dependencies = [
  "httpdate",
  "itoa",
  "pin-project-lite",
- "smallvec",
+ "socket2 0.4.9",
  "tokio",
+ "tower-service",
+ "tracing",
  "want",
 ]
 
-[[package]]
-name = "hyper-util"
-version = "0.1.7"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "cde7055719c54e36e95e8719f95883f22072a48ede39db7fc17a4e1d5281e9b9"
-dependencies = [
- "bytes",
- "futures-util",
- "http",
- "http-body",
- "hyper",
- "pin-project-lite",
- "tokio",
-]
-
 [[package]]
 name = "iana-time-zone"
 version = "0.1.57"
@@ -733,6 +709,16 @@ dependencies = [
  "unicode-normalization",
 ]
 
+[[package]]
+name = "indexmap"
+version = "1.9.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "bd070e393353796e801d209ad339e89596eb4c8d430d18ede6a1cced8fafbd99"
+dependencies = [
+ "autocfg",
+ "hashbrown 0.12.3",
+]
+
 [[package]]
 name = "indexmap"
 version = "2.0.0"
@@ -740,7 +726,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "d5477fe2230a79769d8dc68e0eabf5437907c0457a5614a9e8dddb67f65eb65d"
 dependencies = [
  "equivalent",
- "hashbrown",
+ "hashbrown 0.14.0",
 ]
 
 [[package]]
@@ -862,7 +848,7 @@ version = "0.12.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "1efa59af2ddfad1854ae27d75009d538d0998b4b2fd47083e743ac1a10e46c60"
 dependencies = [
- "hashbrown",
+ "hashbrown 0.14.0",
 ]
 
 [[package]]
@@ -1034,7 +1020,7 @@ checksum = "9b2a4787296e9989611394c33f193f676704af1686e70b8f8033ab5ba9a35a94"
 
 [[package]]
 name = "pgcat"
-version = "1.2.0"
+version = "1.1.2-dev4"
 dependencies = [
  "arc-swap",
  "async-trait",
@@ -1048,9 +1034,7 @@ dependencies = [
  "fallible-iterator",
  "futures",
  "hmac",
- "http-body-util",
  "hyper",
- "hyper-util",
  "itertools",
  "jemallocator",
  "log",
@@ -1494,9 +1478,9 @@ dependencies = [
 
 [[package]]
 name = "smallvec"
-version = "1.13.2"
+version = "1.11.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "3c5e1a9a646d36c3599cd173a41282daf47c44583ad367b8e6837255952e5c67"
+checksum = "62bb4feee49fdd9f707ef802e22365a35de4b7b299de4763d44bfea899442ff9"
 
 [[package]]
 name = "socket2"
@@ -1757,13 +1741,19 @@ version = "0.19.14"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "f8123f27e969974a3dfba720fdb560be359f57b44302d280ba72e76a74480e8a"
 dependencies = [
- "indexmap",
+ "indexmap 2.0.0",
  "serde",
  "serde_spanned",
  "toml_datetime",
  "winnow",
 ]
 
+[[package]]
+name = "tower-service"
+version = "0.3.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b6bc1c9ce2b5135ac7f93c72918fc37feb872bdc6a5533a8b85eb4b86bfdae52"
+
 [[package]]
 name = "tracing"
 version = "0.1.37"

Cargo.toml

@@ -1,6 +1,6 @@
 [package]
 name = "pgcat"
-version = "1.2.0"
+version = "1.1.2-dev4"
 edition = "2021"
 
 # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html
@@ -29,9 +29,7 @@ base64 = "0.21"
 stringprep = "0.1"
 tokio-rustls = "0.24"
 rustls-pemfile = "1"
-http-body-util = "0.1.2"
-hyper = { version = "1.4.1", features = ["full"] }
-hyper-util = { version = "0.1.7", features = ["tokio"] }
+hyper = { version = "0.14", features = ["full"] }
 phf = { version = "0.11.1", features = ["macros"] }
 exitcode = "1.1.2"
 futures = "0.3"

Dockerfile.ci

@@ -1,4 +1,4 @@
-FROM cimg/rust:1.79.0
+FROM cimg/rust:1.67.1
 COPY --from=sclevine/yj /bin/yj /bin/yj
 RUN /bin/yj -h
 RUN sudo apt-get update && \

charts/pgcat/Chart.yaml

@@ -4,5 +4,5 @@ description: A Helm chart for PgCat a PostgreSQL pooler and proxy (like PgBounce
 maintainers:
   - name: Wildcard
     email: support@w6d.io
-appVersion: "1.2.0"
-version: 0.2.0
+appVersion: "1.1.1"
+version: 0.1.0

charts/pgcat/values.yaml

@@ -170,13 +170,13 @@ configuration:
     connect_timeout: 5000
 
     # How long an idle connection with a server is left open (ms).
-    idle_timeout: 30000  # milliseconds
+    idle_timeout: 30000 # milliseconds
 
     # Max connection lifetime before it's closed, even if actively used.
-    server_lifetime: 86400000  # 24 hours
+    server_lifetime: 86400000 # 24 hours
 
     # How long a client is allowed to be idle while in a transaction (ms).
-    idle_client_in_transaction_timeout: 0  # milliseconds
+    idle_client_in_transaction_timeout: 0 # milliseconds
 
     # @param configuration.general.healthcheck_timeout How much time to give `SELECT 1` health check query to return with a result (ms).
     healthcheck_timeout: 1000
@@ -240,15 +240,7 @@ configuration:
   ## the pool_name is what clients use as database name when connecting
   ## For the example below a client can connect using "postgres://sharding_user:sharding_user@pgcat_host:pgcat_port/sharded"
   ## @param [object]
-  pools:
-    [{
-      name: "simple", pool_mode: "transaction",
-      users: [{username: "user", password: "pass", pool_size: 5, statement_timeout: 0}],
-      shards: [{
-        servers: [{host: "postgres", port: 5432, role: "primary"}],
-        database: "postgres"
-      }]
-    }]
+  pools: []
     # - ## default values
     #   ##
     #   ##

src/admin.rs

@@ -55,12 +55,7 @@ where
 
     let query_parts: Vec<&str> = query.trim_end_matches(';').split_whitespace().collect();
 
-    match query_parts
-        .first()
-        .unwrap_or(&"")
-        .to_ascii_uppercase()
-        .as_str()
-    {
+    match query_parts[0].to_ascii_uppercase().as_str() {
         "BAN" => {
             trace!("BAN");
             ban(stream, query_parts).await
@@ -89,12 +84,7 @@ where
             trace!("SHUTDOWN");
             shutdown(stream).await
         }
-        "SHOW" => match query_parts
-            .get(1)
-            .unwrap_or(&"")
-            .to_ascii_uppercase()
-            .as_str()
-        {
+        "SHOW" => match query_parts[1].to_ascii_uppercase().as_str() {
             "HELP" => {
                 trace!("SHOW HELP");
                 show_help(stream).await

src/client.rs

@@ -1204,9 +1204,12 @@ where
                         if !server.in_transaction() {
                             // Report transaction executed statistics.
                             self.stats.transaction();
-                            server
-                                .stats()
-                                .transaction(self.server_parameters.get_application_name());
+                            server.stats().transaction(
+                                Instant::now()
+                                    .duration_since(server.transaction_start().into())
+                                    .as_millis() as u64,
+                                self.server_parameters.get_application_name(),
+                            );
 
                             // Release server back to the pool if we are in transaction mode.
                             // If we are in session mode, we keep the server until the client disconnects.
@@ -1460,9 +1463,12 @@ where
 
                         if !server.in_transaction() {
                             self.stats.transaction();
-                            server
-                                .stats()
-                                .transaction(self.server_parameters.get_application_name());
+                            server.stats().transaction(
+                                Instant::now()
+                                    .duration_since(server.transaction_start().into())
+                                    .as_millis() as u64,
+                                self.server_parameters.get_application_name(),
+                            );
 
                             // Release server back to the pool if we are in transaction mode.
                             // If we are in session mode, we keep the server until the client disconnects.
@@ -1511,9 +1517,12 @@ where
 
                         if !server.in_transaction() {
                             self.stats.transaction();
-                            server
-                                .stats()
-                                .transaction(self.server_parameters.get_application_name());
+                            server.stats().transaction(
+                                Instant::now()
+                                    .duration_since(server.transaction_start().into())
+                                    .as_millis() as u64,
+                                self.server_parameters.get_application_name(),
+                            );
 
                             // Release server back to the pool if we are in transaction mode.
                             // If we are in session mode, we keep the server until the client disconnects.

src/prometheus.rs

@@ -1,11 +1,5 @@
-use http_body_util::Full;
-use hyper::body;
-use hyper::body::Bytes;
-
-use hyper::server::conn::http1;
-use hyper::service::service_fn;
-use hyper::{Method, Request, Response, StatusCode};
-use hyper_util::rt::TokioIo;
+use hyper::service::{make_service_fn, service_fn};
+use hyper::{Body, Method, Request, Response, Server, StatusCode};
 use log::{debug, error, info};
 use phf::phf_map;
 use std::collections::HashMap;
@@ -13,7 +7,6 @@ use std::fmt;
 use std::net::SocketAddr;
 use std::sync::atomic::Ordering;
 use std::sync::Arc;
-use tokio::net::TcpListener;
 
 use crate::config::Address;
 use crate::pool::{get_all_pools, PoolIdentifier};
@@ -250,9 +243,7 @@ impl<Value: fmt::Display> PrometheusMetric<Value> {
     }
 }
 
-async fn prometheus_stats(
-    request: Request<body::Incoming>,
-) -> Result<Response<Full<Bytes>>, hyper::http::Error> {
+async fn prometheus_stats(request: Request<Body>) -> Result<Response<Body>, hyper::http::Error> {
     match (request.method(), request.uri().path()) {
         (&Method::GET, "/metrics") => {
             let mut lines = Vec::new();
@@ -383,35 +374,14 @@ fn push_server_stats(lines: &mut Vec<String>) {
 }
 
 pub async fn start_metric_server(http_addr: SocketAddr) {
-    let listener = TcpListener::bind(http_addr);
-    let listener = match listener.await {
-        Ok(listener) => listener,
-        Err(e) => {
-            error!("Failed to bind prometheus server to HTTP address: {}.", e);
-            return;
-        }
-    };
+    let http_service_factory =
+        make_service_fn(|_conn| async { Ok::<_, hyper::Error>(service_fn(prometheus_stats)) });
+    let server = Server::bind(&http_addr).serve(http_service_factory);
     info!(
         "Exposing prometheus metrics on http://{}/metrics.",
         http_addr
     );
-    loop {
-        let stream = match listener.accept().await {
-            Ok((stream, _)) => stream,
-            Err(e) => {
-                error!("Error accepting connection: {}", e);
-                continue;
-            }
-        };
-        let io = TokioIo::new(stream);
-
-        tokio::task::spawn(async move {
-            if let Err(err) = http1::Builder::new()
-                .serve_connection(io, service_fn(prometheus_stats))
-                .await
-            {
-                eprintln!("Error serving HTTP connection for metrics: {:?}", err);
-            }
-        });
+    if let Err(e) = server.await {
+        error!("Failed to run HTTP server: {}.", e);
     }
 }

src/query_router.rs

@@ -427,12 +427,8 @@ impl QueryRouter {
                         None => (),
                     };
 
-                    let has_locks = !query.locks.is_empty();
-
-                    if has_locks {
-                        self.active_role = Some(Role::Primary);
-                    } else if !visited_write_statement {
-                        // If we already visited a write statement, we should be going to the primary.
+                    // If we already visited a write statement, we should be going to the primary.
+                    if !visited_write_statement {
                         self.active_role = match self.primary_reads_enabled() {
                             false => Some(Role::Replica), // If primary should not be receiving reads, use a replica.
                             true => None,                 // Any server role is fine in this case.
@@ -1162,29 +1158,6 @@ mod test {
         }
     }
 
-    #[test]
-    fn test_select_for_update() {
-        QueryRouter::setup();
-        let mut qr = QueryRouter::new();
-        qr.pool_settings.query_parser_read_write_splitting = true;
-
-        let queries_in_primary_role = vec![
-            simple_query("BEGIN"), // Transaction start
-            simple_query("SELECT * FROM items WHERE id = 5 FOR UPDATE"),
-            simple_query("UPDATE items SET name = 'pumpkin' WHERE id = 5"),
-        ];
-
-        for query in queries_in_primary_role {
-            assert!(qr.infer(&qr.parse(&query).unwrap()).is_ok());
-            assert_eq!(qr.role(), Some(Role::Primary));
-        }
-
-        // query without lock do not change role
-        let query = simple_query("SELECT * FROM items WHERE id = 5");
-        assert!(qr.infer(&qr.parse(&query).unwrap()).is_ok());
-        assert_eq!(qr.role(), None);
-    }
-
     #[test]
     fn test_infer_primary_reads_enabled() {
         QueryRouter::setup();

src/server.rs

@@ -15,6 +15,7 @@ use std::sync::Arc;
 use std::time::SystemTime;
 use tokio::io::{AsyncRead, AsyncReadExt, AsyncWrite, BufStream};
 use tokio::net::TcpStream;
+use tokio::time::Instant;
 use tokio_rustls::rustls::{OwnedTrustAnchor, RootCertStore};
 use tokio_rustls::{client::TlsStream, TlsConnector};
 
@@ -285,6 +286,9 @@ pub struct Server {
     /// Is the server inside a transaction or idle.
     in_transaction: bool,
 
+    /// The time the most recent transaction started.
+    transaction_start: Instant,
+
     /// Is there more data for the client to read.
     data_available: bool,
 
@@ -804,6 +808,7 @@ impl Server {
                         process_id,
                         secret_key,
                         in_transaction: false,
+                        transaction_start: Instant::now(),
                         in_copy_mode: false,
                         data_available: false,
                         bad: false,
@@ -936,6 +941,7 @@ impl Server {
                         // In transaction.
                         'T' => {
                             self.in_transaction = true;
+                            self.transaction_start = Instant::now();
                         }
 
                         // Idle, transaction over.
@@ -1220,6 +1226,12 @@ impl Server {
         self.in_transaction
     }
 
+    /// The start time of the most recent transaction.
+    /// Will be stale if not in a transaction.
+    pub fn transaction_start(&self) -> Instant {
+        self.transaction_start
+    }
+
     /// Currently copying data from client to server or vice-versa.
     pub fn in_copy_mode(&self) -> bool {
         self.in_copy_mode

src/stats/server.rs

@@ -187,11 +187,12 @@ impl ServerStats {
     /// we report each individual queries outside a transaction as a transaction
     /// We only count the initial BEGIN as a transaction, all queries within do not
     /// count as transactions
-    pub fn transaction(&self, application_name: &str) {
+    pub fn transaction(&self, milliseconds: u64, application_name: &str) {
         self.set_application(application_name.to_string());
 
         self.transaction_count.fetch_add(1, Ordering::Relaxed);
         self.address.stats.xact_count_add();
+        self.address.stats.xact_time_add(milliseconds);
     }
 
     /// Report data sent to a server

tests/ruby/admin_spec.rb

@@ -91,27 +91,6 @@ describe "Admin" do
     end
   end
 
-  [
-    "SHOW ME THE MONEY", 
-    "SHOW ME THE WAY", 
-    "SHOW UP", 
-    "SHOWTIME",
-    "HAMMER TIME",
-    "SHOWN TO BE TRUE",
-    "SHOW ",
-    "SHOW     ",
-    "SHOW 1",
-    ";;;;;"
-  ].each do |cmd|
-    describe "Bad command #{cmd}" do
-      it "does not panic and responds with PG::SystemError" do
-        admin_conn = PG::connect(processes.pgcat.admin_connection_string)
-        expect { admin_conn.async_exec(cmd) }.to raise_error(PG::SystemError).with_message(/Unsupported/)
-        admin_conn.close
-      end
-    end
-  end
-
   describe "PAUSE" do
     it "pauses all pools" do
       admin_conn = PG::connect(processes.pgcat.admin_connection_string)

tests/ruby/stats_spec.rb

@@ -16,7 +16,7 @@ describe "Stats" do
       it "updates *_query_time and *_wait_time" do
         connections = Array.new(3) { PG::connect("#{pgcat_conn_str}?application_name=one_query") }
         connections.each do |c|
-          Thread.new { c.async_exec("SELECT pg_sleep(0.25)") }
+          Thread.new { c.async_exec("BEGIN; SELECT pg_sleep(0.25); COMMIT;") }
         end
         sleep(1)
         connections.map(&:close)
@@ -25,10 +25,32 @@ describe "Stats" do
         sleep(15.5)
         admin_conn = PG::connect(processes.pgcat.admin_connection_string)
         results = admin_conn.async_exec("SHOW STATS")[0]
-        admin_conn.close
         expect(results["total_query_time"].to_i).to be_within(200).of(750)
         expect(results["avg_query_time"].to_i).to be_within(50).of(250)
 
+        expect(results["total_xact_time"].to_i).to be_within(200).of(750)
+        expect(results["avg_xact_time"].to_i).to be_within(50).of(250)
+
+        expect(results["total_wait_time"].to_i).to_not eq(0)
+        expect(results["avg_wait_time"].to_i).to_not eq(0)
+
+        connections = Array.new(3) { PG::connect("#{pgcat_conn_str}?application_name=one_query") }
+        connections.each do |c|
+          Thread.new { c.async_exec("SELECT pg_sleep(0.25);") }
+        end
+        sleep(1)
+        connections.map(&:close)
+
+        results = admin_conn.async_exec("SHOW STATS")[0]
+        admin_conn.close
+        # This should increase with more queries
+        expect(results["total_query_time"].to_i).to be_within(400).of(1500)
+        expect(results["avg_query_time"].to_i).to be_within(50).of(250)
+
+        # This should not increase as we did not run any additional transactions
+        expect(results["total_xact_time"].to_i).to be_within(200).of(750)
+        expect(results["avg_xact_time"].to_i).to be_within(50).of(250)
+
         expect(results["total_wait_time"].to_i).to_not eq(0)
         expect(results["avg_wait_time"].to_i).to_not eq(0)
       end