dbt-labs / dbt-labs/dbt

BigQuery: silent jobRateLimitExceeded causes compile freeze on shard-heavy projects

Open
#14,632 11 comments 0 reactions 2 assignees Claimed by @felipecrv View on GitHub
adapter:bigquery area:adapters engine:v2 status:triage
Dominant language
Rust
Stars
13.8k
Forks
2.6k
Avg merge
21h 31m
Merged PRs (30d)
56

Description

> Discussed at [dbt community Slack](https://getdbt.slack.com/archives/C088YCAB6GH/p1779099884444079?thread_ts=1760612531.832169&cid=C088YCAB6GH). Full HTTP/2 capture and follow-up experiment data in collapsed sections below.

## Symptom

`dbtf compile` on a project with ~700 sharded source schemas (introspective queries against `INFORMATION_SCHEMA`) freezes after ~30 seconds. Nothing reaches `dbt.log`. The same workload finishes in 4 min 14 s under dbt-core 1.10.15 + dbt-bigquery 1.10.2 (Python).

## Root cause: Go BigQuery SDK retries `jobRateLimitExceeded` for polling

`googleapis/google-cloud-go:bigquery/bigquery.go` warns explicitly against using `jobRetryReasons` for polling, then does it anyway in `waitForQuery`:

```go
// These reasons are used exclusively for enqueuing jobs (jobs.insert and
// jobs.query). Using them for polling may cause unwanted retries until
// context deadline/cancellation/etc.
jobRetryReasons = []string{"backendError", "rateLimitExceeded", "jobRateLimitExceeded", "internalError"}
```

```go
// bigquery/job.go::waitForQuery
backoff := gax.Backoff{Initial: 50 * time.Millisecond, Multiplier: 1.3, Max: 60 * time.Second}
err := internal.Retry(ctx, backoff, func() (stop bool, err error) {
res, err = call.Do()
if err != nil {
return !retryableError(err, jobRetryReasons), err // jobRateLimitExceeded => retry
}
...
})
```

`jobRateLimitExceeded` was added to the list in [google-cloud-go#9726](https://github.com/googleapis/google-cloud-go/pull/9726) (2024-04-11); polling backoff tuned aggressive in [#10555](https://github.com/googleapis/google-cloud-go/issues/10555) (2024-07-17). The diagnostic captured 1,323 of these 400s in 2 minutes, all absorbed inside this loop.

A controlled probe injecting a synthetic `*googleapi.Error` at arrow-adbc's `runQuery` confirmed errors that reach that point propagate intact to stderr, `dbt.log`, and `query_log.sql`. The production silence is the SDK's retry loop, not arrow-adbc or the Rust adapter.

## Ancillary: arrow-adbc HTTP/2 connection pool

`dbt-labs/arrow-adbc:go/adbc/driver/bigquery/connection.go::newClient` L693 (commit `d2808cf`, pinned in dbt-fusion's `Cargo.toml`) calls `bigquery.NewClient` twice without `option.WithHTTPClient`, so each call builds its own `*http.Transport`. 82% of connections closed at `maxStream=1`. A local patch sharing one HTTP client per `databaseImpl`:

| Metric | Baseline | Patched |
|---|---:|---:|
| HTTP 400 (`jobRateLimitExceeded`) | 5,534 | 3,594 (**−35%**) |
| Highest `maxStream` on a single connection | 25 | **1,967** (**78×**) |
| **Compile completed within 120 s** | **no** | **no** |

Reduces request volume measurably but does not stop the freeze; the SDK still retries forever once quota saturates. Patch diff in the second collapsed section. Not proposing a PR here.

## Workaround

dbt-core 1.10 (Python) finishes the same workload in 4 min 14 s.

## Source pointers

- `googleapis/google-cloud-go:bigquery/bigquery.go` L254-266, `bigquery/job.go` L355-378
- `dbt-labs/arrow-adbc:go/adbc/driver/bigquery/connection.go` L693 (`bigquery.NewClient` at L710, L728); commit `d2808cf`
- `dbt-labs/dbt-fusion:crates/dbt-adapter/src/{engine/mod.rs L103, engine/retry.rs L122, adapter/adapter_impl.rs L586}`

## Environment

dbt Fusion 2.0.0-preview.176, macOS arm64, OAuth (gcloud), no proxy. ~700 sharded source schemas.

HTTP/2 capture and observations

## Setup

A single `dbtf compile --select tag:stg_tripletex` run instrumented with `GODEBUG=http2debug=2` and a `lsof` connection-count probe, killed manually after ~2 minutes when forward progress stopped. Control: `dbt compile` under dbt-core 1.10.15 + dbt-bigquery 1.10.2 (Python) against the same target.

### Capture summary

| Artifact | Size | Notes |
|---|---|---|
| `combined.log` | 330,121 lines | `GODEBUG=http2debug=2` HTTP/2 trace + Rust-side stderr |
| `dbt.log` | 7.96 MB | dbt progress log; stops at 11:57:14, ~30s after start |
| `query_log.sql` | 212,872 lines | Every SQL submitted to BigQuery |
| `conn_count.log` | 496 samples | `lsof` snapshot every 200ms |

The compile was killed at ~11:58:51 (~2 minutes from start). `dbt.log` stops writing model-progress events at 11:57:14, but the HTTP/2 layer continues making real (non-PING) BigQuery requests for another 90 seconds.

### HTTP/2 frame counts

| Frame type | wrote | read |
|---|---|---|
| GOAWAY | 0 | 0 |
| RST_STREAM | 0 | 0 |
| HEADERS | 3,335 | 3,797 |
| DATA | 1,568 | 6,341 |
| SETTINGS | 1,841 | 1,841 |
| PING / PING-ACK | 3,905 | 3,905 |
| WINDOW_UPDATE | 2,255 | 920 |

PING/PING-ACK exchanges continue successfully up to the moment of the kill; the HTTP/2 transport itself is healthy throughout.

### Connection pool: `maxStream` distribution

Go's HTTP/2 transport logs `maxStream=N` (the highest stream ID opened on that connection during its lifetime) when closing each connection. For a healthy multiplexing client this is in the tens or hundreds. The 490 connections closed during the capture:

| maxStream | connections |
|---|---|
| 1 | 445 |
| 15 | 23 |
| 31 | 16 |
| 27 | 3 |
| 51, 33, 23, 213, 11 | 1 each |

**82% of connections served exactly one request.** This is HTTP/1.1-style behavior over HTTP/2: full TLS handshake, full HTTP/2 SETTINGS exchange, one request, close.

Corroborating events:

- 540 × `http2: Transport failed to get client conn for ...: http2: no cached connection was available`
- 540 × `Transport creating client conn` (exact match).
- Bursts of up to 78 new connections per second.

### HTTP response status distribution

| Status | Count | % |
|---|---|---|
| 200 (OK) | 1,993 | 60% |
| 400 (Bad Request) | 1,323 | 40% |
| 499 (cancelled from kill) | 19 | <1% |

### 400 response body

1,312 of the 1,323 400 responses share an identical gzipped body (`content-length=277`):

```json
{
"error": {
"code": 400,
"message": "Job exceeded rate limits: Your user exceeded quota for rate INFORMATION_SCHEMA queries per user. For more information, see https://cloud.google.com/bigquery/docs/troubleshoot-quotas",
"errors": [{
"message": "Job exceeded rate limits: ...",
"domain": "global",
"reason": "jobRateLimitExceeded"
}],
"status": "INVALID_ARGUMENT"
}
}
```

### Workload volume

| Metric | Count |
|---|---|
| Queries submitted | 250 |
| Distinct `query_id` values | 232 |
| Queries containing `UNION ALL` (shard-fanout introspections) | 121 |
| `POST .../jobs` (submissions on the wire) | 298 |
| `GET .../queries/{id}` (poll requests) | 2,121 |

Each `UNION ALL` query fans out across ~91 sharded `INFORMATION_SCHEMA.TABLES` references. Aggregate poll rate observed at 76/sec.

### Model-rendering progress at kill

| Phase | Started | Finished |
|---|---|---|
| Rendering | 1,185 | 843 |
| Analyzing | 828 | 827 |

296 models started rendering and never finished.

### Control: dbt-core 1.10

Same project, same BigQuery target, `dbt compile` under dbt-core 1.10.15 + dbt-bigquery 1.10.2 (Python, 8 threads) completed in **4 min 14 s**, 891 models, no errors.

## Reproduction

```bash
LOGDIR="logs/diag-$(date +%Y%m%d-%H%M%S)"
mkdir -p "$LOGDIR"

# lsof connection probe (separate terminal)
while true; do
count=$(lsof -nP -iTCP -sTCP:ESTABLISHED -c dbt 2>/dev/null | grep -c "443->")
echo "$(date +%s.%N) $count" >> "$LOGDIR/conn_count.log"
sleep 0.2
done &

# Instrumented compile
GODEBUG=http2debug=2 \
RUST_LOG=debug,reqwest=trace,hyper=debug \
dbtf compile \
--log-level trace --log-format-file json \
--log-path "$LOGDIR" \
> "$LOGDIR/combined.log" 2>&1
```

Decoding a 400 response body: extract `data="..."` from a DATA frame following `:status="400"`, decode Go `%q` quoting, gunzip.

Experiment B and C raw data (probe + connection-pool patch validation)

## Experiment B: drop-point probe

### Method

Injected a synthetic, easily-greppable error at the topmost return path of arrow-adbc's `runQuery`. If the literal makes it to some artifact and not to others, the first artifact where it disappears is the drop point.

Patch:

```diff
--- a/go/adbc/driver/bigquery/record_reader.go
+++ b/go/adbc/driver/bigquery/record_reader.go
@@ -36,6 +36,7 @@ import (
"github.com/apache/arrow-go/v18/arrow/memory"
"golang.org/x/sync/errgroup"
+ "google.golang.org/api/googleapi"
"google.golang.org/api/iterator"

func runQuery(...) (...) {
job, err := query.Run(ctx)
+ if err == nil {
+ err = &googleapi.Error{
+ Code: 400,
+ Message: "DROPPOINT_PROBE message body",
+ Errors: []googleapi.ErrorItem{{Reason: "DROPPOINT_PROBE_REASON"}},
+ }
+ }
if err != nil {
return nil, -1, err
}
```

Note: `dbtf compile --select ` served the entire compile out of Fusion's `Frontier` schema cache, so `runQuery` was never called. Switched to `dbtf show --inline "select 1 as DROPPOINT_TEST_QUERY"` to force a real SQL statement through `runQuery`.

### Result

The probe fired and surfaced fully end-to-end. User-visible stderr from the patched build:

```
error: dbt1000: Unknown: [BigQuery] googleapi: Error 400: DROPPOINT_PROBE message body
More details:
Reason: DROPPOINT_PROBE_REASON, Message: (sqlstate: [0, 0, 0, 0, 0], vendor_code: -2147483648)
```

`query_log.sql` entry:

```
-- outcome: error
-- error message: Error { message: "[BigQuery] googleapi: Error 400: DROPPOINT_PROBE message body\nMore details:\nReason: DROPPOINT_PROBE_REASON, Message: \n", status: Unknown, vendor_code: -2147483648, sqlstate: [0, 0, 0, 0, 0], details: Some([]) }
```

Both the outer `Message` and the inner `Errors[0].Reason` reached every log artifact intact (`dbt.log`, `combined.log` stderr, `query_log.sql`). ADBC → Rust → log path drops nothing.

**Conclusion**: the drop is not in arrow-adbc, not in the FFI, not in Fusion's `adbc_error_to_adapter_error`, and not in the adapter's log emission. It is upstream of `runQuery`, inside the Google Go SDK's `waitForQuery` retry loop.

---

## Experiment C: shared `*http.Client` patch (before/after metrics)

### Patch

```diff
--- a/go/adbc/driver/bigquery/bigquery_database.go
+++ b/go/adbc/driver/bigquery/bigquery_database.go
@@ type databaseImpl struct {
tableID string
+ httpClientOnce sync.Once
+ httpClient *http.Client
+ httpClientErr error
}
+
+func (d *databaseImpl) ensureHTTPClient(ctx context.Context, authOptions []option.ClientOption) (*http.Client, error) {
+ d.httpClientOnce.Do(func() {
+ client, _, err := htransport.NewClient(ctx, authOptions...)
+ if err != nil {
+ d.httpClientErr = err; return
+ }
+ d.httpClient = client
+ })
+ return d.httpClient, d.httpClientErr
+}

func (d *databaseImpl) Open(ctx context.Context) (adbc.Connection, error) {
conn := &connectionImpl{
...,
+ databaseRef: d,
}
err := conn.newClient(ctx)

-func (d *databaseImpl) Close() error { return nil }
+func (d *databaseImpl) Close() error {
+ if d.httpClient != nil { d.httpClient.CloseIdleConnections() }
+ return nil
+}
```

```diff
--- a/go/adbc/driver/bigquery/connection.go
+++ b/go/adbc/driver/bigquery/connection.go
@@ type connectionImpl struct {
clientStorageApiDisabled *bigquery.Client
+ databaseRef *databaseImpl
}

func (c *connectionImpl) newClient(ctx context.Context) error {
authOptions, err := c.authOptions(ctx)
...
- storageReadClient, err := bigquery.NewClient(ctx, c.catalog, authOptions...)
+ httpClient, err := c.databaseRef.ensureHTTPClient(ctx, authOptions)
+ if err != nil { return err }
+ bqOptions := append(authOptions, option.WithHTTPClient(httpClient))
+ storageReadClient, err := bigquery.NewClient(ctx, c.catalog, bqOptions...)
...
err = storageReadClient.EnableStorageReadClient(ctx, authOptions...) // gRPC, not bqOptions
...
- client, err := bigquery.NewClient(ctx, c.catalog, authOptions...)
+ client, err := bigquery.NewClient(ctx, c.catalog, bqOptions...)
```

`EnableStorageReadClient` deliberately receives plain `authOptions` because the Storage Read API is gRPC, and `option.WithHTTPClient` has no effect on a gRPC client. Mixing HTTP and gRPC client sharing is a separate concern.

### Full before/after

Both runs: same 120-second `dbtf compile --select tag:stg_tripletex` workload, cold `target/`, default `dev` target.

| Metric | Baseline (unpatched) | Patched (shared-HTTP-client) | Change |
| ---------------------------------------- | -------------------: | ---------------------------: | --------: |
| `combined.log` HTTP/2 trace size | 47.3 MB | 34.6 MB | **−27%** |
| HTTP 200 responses | 2,372 | 2,186 | −8% |
| **HTTP 400 (`jobRateLimitExceeded`)** | **5,534** | **3,594** | **−35%** |
| Closed connections at `maxStream=1` | 701 | 475 | −32% |
| Connections at `maxStream=15` | 119 | 0 | −100% |
| **Highest `maxStream` on a single conn** | 25 | **1,967** | 78× |
| Peak concurrent connections (lsof) | 2 | 1 | half |
| Average concurrent connections | 1.8 | 0.8 | −56% |
| `query_log.sql` success queries | 243 | 244 | ~same |
| **`query_log.sql` error queries** | **127** | **0** | **−100%** |
| Compile completed within 120 s? | no (killed) | no (killed) | unchanged |

Three independent signals confirm the patch works:

1. **HTTP/2 multiplexing engages.** Baseline top `maxStream` was 25 across 822 closed connections. Patched has one connection carrying 1,967 streams. That is the multiplexing-actually-works signature.
2. **Request volume drops.** 35% fewer HTTP 400s in the same window means less pressure on the per-user `INFORMATION_SCHEMA` quota.
3. **Auxiliary 1-second cancellations vanish.** 127 baseline queries hit `Job execution was cancelled: Job timed out after 1 sec, stopped`. Patched had 0. Both runs had the `job_execution_timeout_seconds: 1800000` profile workaround in place; the difference is not the profile, it is that the patched run spent less time on transport handshakes and more time inside actual BigQuery polls.

### What the patch does NOT do

The compile still froze. The patch reduces the *rate* at which the system enters saturated-retry but does not stop `google-cloud-go:bigquery/job.go::waitForQuery` from retrying `jobRateLimitExceeded` internally. With the patch, fewer rate-limit responses come back per second; without an upstream change to that retry policy, the loop still fires forever once quota is saturated.

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.