BigQuery: silent jobRateLimitExceeded causes compile freeze on shard-heavy projects
- 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
Assessment
This issue has not been assessed yet.