search

trinodb / trino

Official repository of Trino, the distributed SQL query engine for big data, formerly known as PrestoSQL (https://trino.io)
https://trino.io
Apache License 2.0
10.23k stars 2.95k forks source link

Worker OOM after the query is finished #20112

Closed 13535048320 closed 3 months ago

13535048320 commented 9 months ago

After the query is completed, the memory used by the worker continues to increase until the worker OOM kill.

Trino: 430 Iceberg: 1.3.1 Filesystem: Minio Catalog hive-standalone-metastore: 3.1.3 Total number of data rows: 80 million

Properties

datalake: |-
    connector.name=iceberg
    iceberg.file-format=PARQUET
    iceberg.catalog.type=hive_metastore
    iceberg.hive-catalog-name=datalake
    iceberg.unique-table-location=false
    hive.metastore.uri=thrift://hivet:9083
    hive.s3.endpoint=http://minio:9000
    hive.s3.aws-access-key=user
    hive.s3.aws-secret-key=pass

DDL

CREATE TABLE datalake.dwd.dwd_ausp_streaming (
   objek varchar NOT NULL,
   atinn varchar NOT NULL,
   atzhl varchar NOT NULL,
   mafid varchar NOT NULL,
   klart varchar NOT NULL,
   adzhl varchar NOT NULL,
   atflv real,
   dwd_data_time timestamp(6)
)
WITH (
   format = 'PARQUET',
   format_version = 2,
   location = 's3a://warehouse/dwd.db/dwd_ausp_streaming'
)

Query

SELECT * FROM datalake.dwd.dwd_ausp_streaming LIMIT 10;

Coordinator logs image

2023-12-14T07:21:00.391Z        DEBUG   stage-scheduler io.trino.execution.scheduler.PipelinedStageExecution    Pipelined stage execution 20231214_072054_00157_yk3km.0 is FLUSHING
2023-12-14T07:21:00.393Z        DEBUG   stage-scheduler io.trino.execution.scheduler.PipelinedStageExecution    Pipelined stage execution 20231214_072054_00157_yk3km.1 is CANCELED
2023-12-14T07:21:00.625Z        DEBUG   dispatcher-query-254    io.trino.execution.StageStateMachine    Stage 20231214_072054_00157_yk3km.0 is PENDING
2023-12-14T07:21:00.628Z        DEBUG   stage-scheduler io.trino.execution.scheduler.PipelinedStageExecution    Pipelined stage execution 20231214_072054_00157_yk3km.0 is FINISHED
2023-12-14T07:21:00.712Z        DEBUG   dispatcher-query-253    io.trino.execution.StageStateMachine    Stage 20231214_072054_00157_yk3km.0 is FINISHED
2023-12-14T07:21:00.716Z        DEBUG   dispatcher-query-256    io.trino.execution.StageStateMachine    Stage 20231214_072054_00157_yk3km.1 is FINISHED
2023-12-14T07:21:00.716Z        DEBUG   dispatcher-query-254    io.trino.execution.QueryStateMachine    Query 20231214_072054_00157_yk3km is FINISHING
2023-12-14T07:21:00.725Z        DEBUG   dispatcher-query-254    io.trino.execution.QueryStateMachine    Query 20231214_072054_00157_yk3km is FINISHED
2023-12-14T07:21:01.725Z        DEBUG   dispatch-executor-3     io.trino.execution.QueryTracker Remove query 20231214_024927_00057_yk3km
2023-12-14T07:21:02.337Z        WARN    TaskInfoFetcher-20231214_071603_00156_yk3km.1.0.0-1394  io.trino.server.remotetask.RequestErrorTracker  Error getting info for task 20231214_071603_00156_yk3km.1.0.0: java.util.concurrent.TimeoutException: Total timeout 10000 ms elapsed: http://10.244.5.164:8080/v1/task/20231214_071603_00156_yk3km.1.0.0
2023-12-14T07:21:02.340Z        WARN    TaskInfoFetcher-20231214_022740_00030_yk3km.0.0.0-1410  io.trino.server.remotetask.RequestErrorTracker  Error getting info for task 20231214_022740_00030_yk3km.0.0.0: java.util.concurrent.TimeoutException: Total timeout 10000 ms elapsed: http://10.244.5.164:8080/v1/task/20231214_022740_00030_yk3km.0.0.0
2023-12-14T07:21:19.491Z        DEBUG   http-worker-1232        io.trino.security.AccessControl Invocation of checkCanSetUser(principal=Optional[trino], userName='trino') succeeded in 23.31us
2023-12-14T07:21:19.491Z        DEBUG   http-worker-1232        io.trino.security.AccessControl Invocation of filterQueriesOwnedBy(identity=Identity{user='trino', principal=trino}, queryOwners=[]) succeeded in 30.43us
2023-12-14T07:21:19.883Z        WARN    ContinuousTaskStatusFetcher-20231214_071603_00156_yk3km.1.0.0-1448      io.trino.server.remotetask.RequestErrorTracker  Error getting task status 20231214_071603_00156_yk3km.1.0.0: Server refused connection: http://10.244.5.164:8080/v1/task/20231214_071603_00156_yk3km.1.0.0/status: http://10.244.5.164:8080/v1/task/20231214_071603_00156_yk3km.1.0.0
2023-12-14T07:21:20.385Z        WARN    ContinuousTaskStatusFetcher-20231214_071603_00156_yk3km.1.0.0-1448      io.trino.server.remotetask.RequestErrorTracker  Error getting task status 20231214_071603_00156_yk3km.1.0.0: Server refused connection: http://10.244.5.164:8080/v1/task/20231214_071603_00156_yk3km.1.0.0/status: http://10.244.5.164:8080/v1/task/20231214_071603_00156_yk3km.1.0.0
2023-12-14T07:21:20.563Z        DEBUG   http-worker-1171        io.trino.security.AccessControl Invocation of checkCanSetUser(principal=Optional[trino], userName='trino') succeeded in 28.74us
2023-12-14T07:21:20.563Z        DEBUG   http-worker-1171        io.trino.security.AccessControl Invocation of filterQueriesOwnedBy(identity=Identity{user='trino', principal=trino}, queryOwners=[]) succeeded in 13.00us
2023-12-14T07:21:20.887Z        WARN    ContinuousTaskStatusFetcher-20231214_071603_00156_yk3km.1.0.0-1448      io.trino.server.remotetask.RequestErrorTracker  Error getting task status 20231214_071603_00156_yk3km.1.0.0: Server refused connection: http://10.244.5.164:8080/v1/task/20231214_071603_00156_yk3km.1.0.0/status: http://10.244.5.164:8080/v1/task/20231214_071603_00156_yk3km.1.0.0
2023-12-14T07:21:21.897Z        WARN    TaskInfoFetcher-20231214_021421_00015_yk3km.1.0.0-1448  io.trino.server.remotetask.RequestErrorTracker  Error getting info for task 20231214_021421_00015_yk3km.1.0.0: Server refused connection: http://10.244.5.164:8080/v1/task/20231214_021421_00015_yk3km.1.0.0?summarize: http://10.244.5.164:8080/v1/task/20231214_021421_00015_yk3km.1.0.0
2023-12-14T07:21:21.897Z        WARN    ContinuousTaskStatusFetcher-20231214_071603_00156_yk3km.1.0.0-1410      io.trino.server.remotetask.RequestErrorTracker  Error getting task status 20231214_071603_00156_yk3km.1.0.0: Server refused connection: http://10.244.5.164:8080/v1/task/20231214_071603_00156_yk3km.1.0.0/status: http://10.244.5.164:8080/v1/task/20231214_071603_00156_yk3km.1.0.0
2023-12-14T07:21:21.971Z        DEBUG   http-worker-1367        io.trino.security.AccessControl Invocation of checkCanSetUser(principal=Optional[trino], userName='trino') succeeded in 27.32us
2023-12-14T07:21:21.972Z        DEBUG   http-worker-1367        io.trino.security.AccessControl Invocation of filterQueriesOwnedBy(identity=Identity{user='trino', principal=trino}, queryOwners=[]) succeeded in 11.74us
2023-12-14T07:21:23.489Z        DEBUG   http-worker-1248        io.trino.security.AccessControl Invocation of checkCanSetUser(principal=Optional[trino], userName='trino') succeeded in 35.79us
......
2023-12-14T07:22:01.813Z        DEBUG   http-worker-1356        io.trino.security.AccessControl Invocation of filterQueriesOwnedBy(identity=Identity{user='trino', principal=trino}, queryOwners=[]) succeeded in 19.91us
2023-12-14T07:22:02.085Z        DEBUG   query-management-1      io.trino.memory.ClusterMemoryLeakDetector       Memory leak detected. The following queries are already finished, but they have memory reservations on some worker node(s): {20231214_072054_00157_yk3km=1280}
2023-12-14T07:22:03.087Z        DEBUG   query-management-3      io.trino.memory.ClusterMemoryLeakDetector       Memory leak detected. The following queries are already finished, but they have memory reservations on some worker node(s): {20231214_072054_00157_yk3km=1280}

Worker logs

2023-12-14T07:27:03.395Z        DEBUG   task-notification-3     io.trino.execution.TaskStateMachine     Task 20231214_072703_00160_yk3km.1.1.0 is RUNNING
2023-12-14T07:27:03.836Z        DEBUG   Task-20231214_072703_00160_yk3km.1.1.0-98       io.trino.execution.executor.timesharing.TimeSharingTaskExecutor Task scheduled 20231214_072703_00160_yk3km.1.1.0
2023-12-14T07:27:03.874Z        DEBUG   20231214_072703_00160_yk3km.1.1.0-16-74 io.trino.util.CompilerUtils     Defining class: io/trino/$gen/PageWithPositionComparator_20231214_072703_39
2023-12-14T07:27:04.127Z        DEBUG   20231214_072703_00160_yk3km.1.1.0-3-58  io.trino.util.CompilerUtils     Defining class: io/trino/$gen/PagesIndexComparator_20231214_072704_40
2023-12-14T07:27:04.143Z        DEBUG   20231214_072703_00160_yk3km.1.1.0-2-72  io.trino.execution.executor.timesharing.TimeSharingTaskExecutor Split 20231214_072703_00160_yk3km.1.1.0-2  (start = 1.73726026921385E8, wall = 295 ms, cpu = 11 ms, wait = 3 ms, calls = 3) is finished
2023-12-14T07:27:04.143Z        DEBUG   20231214_072703_00160_yk3km.1.1.0-3-58  io.trino.execution.executor.timesharing.TimeSharingTaskExecutor Split 20231214_072703_00160_yk3km.1.1.0-3  (start = 1.73726026922057E8, wall = 295 ms, cpu = 18 ms, wait = 2 ms, calls = 3) is finished
2023-12-14T07:27:04.249Z        DEBUG   task-notification-3     io.trino.execution.TaskStateMachine     Task 20231214_072703_00160_yk3km.1.1.0 is FLUSHING
2023-12-14T07:27:04.261Z        DEBUG   http-worker-96  io.trino.execution.SqlTask      Aborting task 20231214_072703_00160_yk3km.1.1.0 output 0
2023-12-14T07:27:04.263Z        DEBUG   task-notification-4     io.trino.execution.TaskStateMachine     Task 20231214_072703_00160_yk3km.1.1.0 is FINISHED
2023-12-14T07:27:04.266Z        DEBUG   Task-20231214_072703_00160_yk3km.1.1.0-119      io.trino.execution.executor.timesharing.TimeSharingTaskExecutor Task finished or failed 20231214_072703_00160_yk3km.1.1.0
2023-12-14T07:30:00.158Z        DEBUG   task-notification-3     io.trino.execution.TaskStateMachine     Task 20231214_072959_00163_yk3km.1.1.0 is RUNNING
2023-12-14T07:30:00.174Z        DEBUG   Task-20231214_072959_00163_yk3km.1.1.0-113      io.trino.execution.executor.timesharing.TimeSharingTaskExecutor Task scheduled 20231214_072959_00163_yk3km.1.1.0
2023-12-14T07:30:00.187Z        DEBUG   task-notification-3     io.trino.execution.TaskStateMachine     Task 20231214_072959_00163_yk3km.1.1.0 is ABORTING
2023-12-14T07:30:00.189Z        DEBUG   20231214_072959_00163_yk3km.1.1.0-9-80  io.trino.execution.executor.timesharing.TimeSharingTaskExecutor Split 20231214_072959_00163_yk3km.1.1.0-9  (start = 1.73902363449178E8, wall = 4 ms, cpu = 1 ms, wait = 2 ms, calls = 1) is finished
2023-12-14T07:30:00.189Z        DEBUG   20231214_072959_00163_yk3km.1.1.0-15-86 io.trino.execution.executor.timesharing.TimeSharingTaskExecutor Split 20231214_072959_00163_yk3km.1.1.0-15  (start = 1.73902365581287E8, wall = 2 ms, cpu = 1 ms, wait = 4 ms, calls = 1) is finished
2023-12-14T07:30:00.203Z        DEBUG   Task-20231214_072959_00163_yk3km.1.1.0-118      io.trino.execution.executor.timesharing.TimeSharingTaskExecutor Task finished or failed 20231214_072959_00163_yk3km.1.1.0
2023-12-14T07:30:00.204Z        DEBUG   20231214_072959_00163_yk3km.1.1.0-12-71 io.trino.execution.executor.timesharing.TimeSharingTaskExecutor Split 20231214_072959_00163_yk3km.1.1.0-12  (start = 1.73902364654349E8, wall = 19 ms, cpu = 2 ms, wait = 16 ms, calls = 2) is finished
2023-12-14T07:30:00.219Z        DEBUG   task-notification-1     io.trino.execution.TaskStateMachine     Task 20231214_072959_00163_yk3km.1.1.0 is ABORTED

2023-12-14T07:47:00.634Z        DEBUG   task-notification-1     io.trino.execution.TaskStateMachine     Task 20231214_074700_00166_yk3km.1.0.0 is RUNNING
2023-12-14T07:47:00.645Z        DEBUG   task-notification-0     io.trino.execution.TaskStateMachine     Task 20231214_074700_00166_yk3km.0.0.0 is RUNNING
2023-12-14T07:47:00.782Z        DEBUG   Task-20231214_074700_00166_yk3km.0.0.0-112      io.trino.util.CompilerUtils     Defining class: io/trino/$gen/SingleLongState_20231214_074700_41
2023-12-14T07:47:00.791Z        DEBUG   Task-20231214_074700_00166_yk3km.0.0.0-112      io.trino.util.CompilerUtils     Defining class: io/trino/$gen/GroupedLongState_20231214_074700_42
2023-12-14T07:47:00.794Z        DEBUG   Task-20231214_074700_00166_yk3km.0.0.0-112      io.trino.util.CompilerUtils     Defining class: io/trino/$gen/LongStateFactory_20231214_074700_43
2023-12-14T07:47:00.830Z        DEBUG   Task-20231214_074700_00166_yk3km.0.0.0-112      io.trino.util.CompilerUtils     Defining class: io/trino/$gen/countAccumulator_20231214_074700_44
2023-12-14T07:47:00.838Z        DEBUG   Task-20231214_074700_00166_yk3km.0.0.0-112      io.trino.util.CompilerUtils     Defining class: io/trino/$gen/countGroupedAccumulator_20231214_074700_45
2023-12-14T07:47:00.850Z        DEBUG   Task-20231214_074700_00166_yk3km.0.0.0-112      io.trino.util.CompilerUtils     Defining class: io/trino/$gen/AggregationMaskBuilder_20231214_074700_46
2023-12-14T07:47:00.859Z        DEBUG   Task-20231214_074700_00166_yk3km.0.0.0-112      io.trino.execution.executor.timesharing.TimeSharingTaskExecutor Task scheduled 20231214_074700_00166_yk3km.0.0.0
2023-12-14T07:47:00.884Z        DEBUG   Task-20231214_074700_00166_yk3km.1.0.0-202      io.trino.execution.executor.timesharing.TimeSharingTaskExecutor Task scheduled 20231214_074700_00166_yk3km.1.0.0
2023-12-14T07:47:03.871Z        DEBUG   20231214_074700_00166_yk3km.1.0.0-15-72 io.trino.parquet.reader.ParquetReader   advanceToNextRowGroup dataSource s3a://uat-warehouse/dwd.db/dwd_ausp_streaming/data/00012-0-3b4c8277-c38a-466f-b5d3-1bb6196144e2-00010.parquet, currentRowGroup 0, rowRanges null, currentBlockMetadata BlockMetaData{568614, 17487419 [ColumnMetaData{GZIP [objek] required binary objek (STRING) = 1  [BIT_PACKED, PLAIN], 4}, ColumnMetaData{GZIP [atinn] required binary atinn (STRING) = 2  [PLAIN_DICTIONARY, BIT_PACKED], 2023173}, ColumnMetaData{GZIP [atzhl] required binary atzhl (STRING) = 3  [PLAIN_DICTIONARY, BIT_PACKED], 2109345}, ColumnMetaData{GZIP [mafid] required binary mafid (STRING) = 4  [PLAIN_DICTIONARY, BIT_PACKED], 2118879}, ColumnMetaData{GZIP [klart] required binary klart (STRING) = 5  [PLAIN_DICTIONARY, BIT_PACKED], 2120358}, ColumnMetaData{GZIP [adzhl] required binary adzhl (STRING) = 6  [PLAIN_DICTIONARY, BIT_PACKED], 2123133}, ColumnMetaData{GZIP [atflv] optional float atflv = 7  [PLAIN_DICTIONARY, RLE, BIT_PACKED], 2170687}, ColumnMetaData{GZIP [dwd_data_time] optional int64 dwd_data_time (TIMESTAMP(MICROS,false)) = 8  [RLE, BIT_PACKED, PLAIN], 2370175}]}
2023-12-14T07:47:03.871Z        DEBUG   20231214_074700_00166_yk3km.1.0.0-0-88  io.trino.parquet.reader.ParquetReader   advanceToNextRowGroup dataSource s3a://uat-warehouse/dwd.db/dwd_ausp_streaming/data/00019-0-10f018e1-767e-45f4-a37f-20221a7dc023-00006.parquet, currentRowGroup 0, rowRanges null, currentBlockMetadata BlockMetaData{1110021, 34323024 [ColumnMetaData{GZIP [objek] required binary objek (STRING) = 1  [BIT_PACKED, PLAIN], 4}, ColumnMetaData{GZIP [atinn] required binary atinn (STRING) = 2  [PLAIN_DICTIONARY, BIT_PACKED], 4247183}, ColumnMetaData{GZIP [atzhl] required binary atzhl (STRING) = 3  [PLAIN_DICTIONARY, BIT_PACKED], 4493649}, ColumnMetaData{GZIP [mafid] required binary mafid (STRING) = 4  [PLAIN_DICTIONARY, BIT_PACKED], 4517202}, ColumnMetaData{GZIP [klart] required binary klart (STRING) = 5  [PLAIN_DICTIONARY, BIT_PACKED], 4520004}, ColumnMetaData{GZIP [adzhl] required binary adzhl (STRING) = 6  [PLAIN_DICTIONARY, BIT_PACKED], 4530180}, ColumnMetaData{GZIP [atflv] optional float atflv = 7  [PLAIN_DICTIONARY, RLE, BIT_PACKED], 4621886}, ColumnMetaData{GZIP [dwd_data_time] optional int64 dwd_data_time (TIMESTAMP(MICROS,false)) = 8  [RLE, BIT_PACKED, PLAIN], 5054274}]}
......

Helm values.yaml

image:
  repository: trinodb/trino
  pullPolicy: IfNotPresent
  tag: 430

imagePullSecrets:
  - name: registry-credentials

server:
  workers: 3
  node:
    environment: production
    dataDir: /data/trino
    pluginDir: /usr/lib/trino/plugin
  log:
    trino:
      level: DEBUG
  config:
    path: /etc/trino
    http:
      port: 8080
    https:
      enabled: true
      port: 9443
      keystore:
        path: "/etc/trino/keystore.jks/keystore.jks"
    authenticationType: "PASSWORD"
    internalCommunication:
      sharedSecret: ""
    query:
      maxMemory: "8GB"
  exchangeManager:
    name: "filesystem"
    baseDir: "/tmp/trino-local-file-system-exchange-manager"
  workerExtraConfig: ""
  coordinatorExtraConfig: ""
  autoscaling:
    enabled: false
    maxReplicas: 5
    targetCPUUtilizationPercentage: 50

accessControl: {}
additionalNodeProperties: {}
additionalConfigProperties: {}
additionalLogProperties: {}
additionalExchangeManagerProperties: {}
eventListenerProperties: {}

additionalCatalogs:
  datalake: |-
    connector.name=iceberg
    iceberg.file-format=PARQUET
    iceberg.catalog.type=hive_metastore
    iceberg.hive-catalog-name=datalake
    iceberg.unique-table-location=false
    hive.metastore.uri=thrift://hive:9083
    hive.s3.endpoint=http://minio:9000
    hive.s3.aws-access-key=
    hive.s3.aws-secret-key=
  es: |-
    connector.name=elasticsearch
    elasticsearch.host=elasticsearch-es-internal-http.default
    elasticsearch.port=9200
    elasticsearch.default-schema-name=default
    elasticsearch.security=PASSWORD
    elasticsearch.auth.user=
    elasticsearch.auth.password=

env: []
envFrom: []
initContainers: {}
sidecarContainers: {}

securityContext:
  runAsUser: 1000
  runAsGroup: 1000

shareProcessNamespace:
  coordinator: false
  worker: false

service:
  type: ClusterIP
  port: 9443

auth:
  passwordAuth: ""

serviceAccount:
  create: false
  name: ""
  annotations: {}

secretMounts: []

coordinator:
  jvm:
    maxHeapSize: "12G"
    gcMethod:
      type: "UseG1GC"
      g1:
        heapRegionSize: "32M"
  config:
    memory:
      heapHeadroomPerNode: ""
    query:
      maxMemoryPerNode: "8GB"

  additionalJVMConfig: {}
  additionalExposedPorts: {}
  resources: {}
  livenessProbe: {}
  readinessProbe: {}
  nodeSelector: {}
  tolerations: []
  affinity: {}
  additionalConfigFiles: {}
  annotations: {}
  labels: {}

  secretMounts:
    - name: keystore
      secretName: keystore
      path: /etc/trino/keystore.jks

worker:
  jvm:
    maxHeapSize: "24G"
    gcMethod:
      type: "UseG1GC"
      g1:
        heapRegionSize: "32M"
  config:
    memory:
      heapHeadroomPerNode: ""
    query:
      maxMemoryPerNode: "8GB"

  additionalJVMConfig: {}
  additionalExposedPorts: {}
  resources: {}
  livenessProbe: {}
  readinessProbe: {}
  nodeSelector: {}
  tolerations: []
  affinity: {}
  additionalConfigFiles: {}
  annotations: {}
  labels: {}

  secretMounts:
    - name: keystore
      secretName: keystore
      path: /etc/trino/keystore.jks

kafka:
  mountPath: "/etc/trino/schemas"
  tableDescriptions: {}

commonLabels: {}  # Labels that get applied to every resource's metadata
ingress:
  enabled: false
  className: "nginx"
  annotations: {}
  hosts:
    - host: trino-uat-cluster.example.com
      paths:
        - path: /
          pathType: Prefix
  tls:
    - secretName: pt-tls
      hosts:
        - pacific-textiles.com
luckydogxf commented 9 months ago

I run into the same issue, too. will someone help us ?

raunaqmorarka commented 3 months ago

We can't do much about this unless we have a heap dump showing what is using the memory. There have been improvements around memory usage and accounting in recent releases, I would suggest trying latest release and filing an issue with a heap dump if the problem persists.