OutOfMemoryError Java heap space during snapshot of large bytea table [DBZ-2540]
- Dominant language
- HTML
- Stars
- 6
- Forks
- 8
- Avg merge
- 2d 19h
- Merged PRs (30d)
- 1
Description
Migrated from [DBZ-2540](https://issues.redhat.com/browse/DBZ-2540)
I can successfully reproduce the following issue at will. Please let me know what I can do to provide further information.
I have a particular postgres table which is only 9000 rows and 500MB in size, but it is a bit unique in that it has bytea data with the largest row being 6MB in size. I have the Kafka topic configured to allow the max of 8MB and I also know for a fact that I have published near-8MB messages successfully, though of TEXT, not BYTEA, type. Here is the schema of the table:
{code:java}
Table "jfinzel.test_broken_dbz"
Column | Type | Collation | Nullable | Default
-------------------------------+--------------------------+-----------+----------+---------
id | integer | | not null |
created_on | timestamp with time zone | | |
method_id | smallint | | |
failed | boolean | | |
failed_description | text | | |
created_by | character varying(30) | | |
contents | bytea | | |
name | character varying(32) | | |
created_date | date | | |
last_changed_at | timestamp with time zone | | |
Indexes:
"test_broken_dbz_pkey" PRIMARY KEY, btree (id)
Publications:
"dbz_publication" {code}
Even after tweaking JAVA_HEAP_OPTS, I am getting out of memory errors trying to run a snapshot of this table. Here is the stack trace:
{code:java}
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,506 INFO Postgres|foo_prod|postgres-connector-task Snapshot - Final stage [io.debezium.pipeline.source.AbstractSnapshotChangeEventSource]
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,508 ERROR Postgres|foo_prod|postgres-connector-task Producer failure [io.debezium.pipeline.ErrorHandler]
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m java.lang.RuntimeException: org.postgresql.util.PSQLException: This connection has been closed.
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.relational.RelationalSnapshotChangeEventSource.rollbackTransaction(RelationalSnapshotChangeEventSource.java:435)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.relational.RelationalSnapshotChangeEventSource.doExecute(RelationalSnapshotChangeEventSource.java:152)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.pipeline.source.AbstractSnapshotChangeEventSource.execute(AbstractSnapshotChangeEventSource.java:63)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:96)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.lang.Thread.run(Thread.java:834)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m Caused by: org.postgresql.util.PSQLException: This connection has been closed.
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:865)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at org.postgresql.jdbc.PgConnection.rollback(PgConnection.java:872)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.relational.RelationalSnapshotChangeEventSource.rollbackTransaction(RelationalSnapshotChangeEventSource.java:432)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011... 8 more
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,511 INFO Postgres|foo_prod|postgres-connector-task Connected metrics set to 'false' [io.debezium.pipeline.metrics.StreamingChangeEventSourceMetrics]
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,508 ERROR || [Worker clientId=connect-1, groupId=debezium-postgres-staging] Uncaught exception in herder work thread, exiting: [org.apache.kafka.connect.runtime.distributed.DistributedHerder]
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m java.lang.OutOfMemoryError: Java heap space
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,671 INFO || Kafka Connect stopping [org.apache.kafka.connect.runtime.Connect]
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,673 INFO || Stopping REST server [org.apache.kafka.connect.runtime.rest.RestServer]
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,679 INFO || Stopped http_1.1.1.18083@7df76d99{HTTP/1.1,[http/1.1]}{1.1.1.1:8083} [org.eclipse.jetty.server.AbstractConnector]
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,679 INFO || node0 Stopped scavenging [org.eclipse.jetty.server.session]
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,684 INFO || REST server stopped [org.apache.kafka.connect.runtime.rest.RestServer]
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,684 INFO || [Worker clientId=connect-1, groupId=debezium-postgres-staging] Herder stopping [org.apache.kafka.connect.runtime.distributed.DistributedHerder]
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,723 INFO || WorkerSourceTask{id=foo_prod:debezium_postgres_snapshot-0} Committing offsets [org.apache.kafka.connect.runtime.WorkerSourceTask]
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,723 INFO || WorkerSourceTask{id=foo_prod:debezium_postgres_snapshot-0} flushing 0 outstanding messages for offset commit [org.apache.kafka.connect.runtime.WorkerSourceTask]
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,723 ERROR || WorkerSourceTask{id=foo_prod:debezium_postgres_snapshot-0} Task threw an uncaught and unrecoverable exception [org.apache.kafka.connect.runtime.WorkerTask]
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m org.apache.kafka.connect.errors.ConnectException: An exception occurred in the change event producer. This connector will be stopped.
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.pipeline.ErrorHandler.setProducerThrowable(ErrorHandler.java:42)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:117)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at java.base/java.lang.Thread.run(Thread.java:834)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m Caused by: java.lang.RuntimeException: org.postgresql.util.PSQLException: This connection has been closed.
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.relational.RelationalSnapshotChangeEventSource.rollbackTransaction(RelationalSnapshotChangeEventSource.java:435)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.relational.RelationalSnapshotChangeEventSource.doExecute(RelationalSnapshotChangeEventSource.java:152)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.pipeline.source.AbstractSnapshotChangeEventSource.execute(AbstractSnapshotChangeEventSource.java:63)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:96)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011... 5 more
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m Caused by: org.postgresql.util.PSQLException: This connection has been closed.
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:865)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at org.postgresql.jdbc.PgConnection.rollback(PgConnection.java:872)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011at io.debezium.relational.RelationalSnapshotChangeEventSource.rollbackTransaction(RelationalSnapshotChangeEventSource.java:432)
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m #011... 8 more
Sep 15 10:15:42 dbz-stage-01 docker-compose[45685]: #033[33mconnect_2 |#033[0m 2020-09-15 15:15:42,723 ERROR || WorkerSourceTask{id=foo_prod:debezium_postgres_snapshot-0} Task is being killed and will not recover until manually restarted [org.apache.kafka.connect.runtime.WorkerTask]{code}
My Kafka Connect settings:
{code:java}
version: '2'
services:
connect:
image: debezium/connect:1.2.1.Final
ports:
- "127.0.0.1:8083-8084:8083"
volumes:
- /etc/kafka/secrets:/etc/kafka/secrets
environment:
- BOOTSTRAP_SERVERS=pkc-my.region.aws.confluent.cloud:9092
- GROUP_ID=debezium-postgres-staging
- CONFIG_STORAGE_TOPIC=dbz_pg_connect_configs
- OFFSET_STORAGE_TOPIC=dbz_pg_connect_offsets
- STATUS_STORAGE_TOPIC=dbz_pg_connect_statuses
- CONNECT_CONFIG_PROVIDERS=file
- CONNECT_CONFIG_PROVIDERS_FILE_CLASS=org.apache.kafka.common.config.provider.FileConfigProvider
- CONNECT_CONFIG_STORAGE_REPLICATION_FACTOR=3
- CONNECT_OFFSET_STORAGE_REPLICATION_FACTOR=3
- CONNECT_STATUS_STORAGE_REPLICATION_FACTOR=3
- OFFSET_FLUSH_INTERVAL_MS=8000
- OFFSET_FLUSH_TIMEOUT_MS=60000
- CONNECT_PRODUCER_MAX_REQUEST_SIZE=8388608
- CONNECT_HEARTBEAT_INTERVAL_MS=10000
- CONNECT_SESSION_TIMEOUT_MS=30000
- CONNECT_KAFKA_HEAP_OPTS=-Xms1g -Xmx3g
- CONNECT_SECURITY_PROTOCOL=SASL_SSL
- CONNECT_SASL_MECHANISM=PLAIN
- CONNECT_SASL_JAAS_CONFIG=org.apache.kafka.common.security.plain.PlainLoginModule required username="foo" password="bar";
- CONNECT_PRODUCER_SECURITY_PROTOCOL=SASL_SSL
- CONNECT_PRODUCER_SASL_JAAS_CONFIG=org.apache.kafka.common.security.plain.PlainLoginModule required username="foo" password="bar";
- CONNECT_PRODUCER_SASL_MECHANISM=PLAIN
- CONNECT_CONSUMER_SECURITY_PROTOCOL=SASL_SSL
- CONNECT_CONSUMER_SASL_JAAS_CONFIG=org.apache.kafka.common.security.plain.PlainLoginModule required username="foo" password="bar";
- CONNECT_CONSUMER_SASL_MECHANISM=PLAIN {code}
My connector config:
{code:java}
{
"config": {
"binary.handling.mode": "base64",
"connector.class": "io.debezium.connector.postgresql.PostgresConnector",
"database.dbname": "foo_prod",
"database.hostname": "foo.example.com",
"database.password": "${file:/etc/kafka/secrets/connect.properties:PG_PASSWORD}",
"database.port": "5432",
"database.server.name": "foo_prod",
"database.user": "${file:/etc/kafka/secrets/connect.properties:PG_USERNAME}",
"datatype.propagate.source.type": ".+\\.numeric,.+\\.bytea",
"decimal.handling.mode": "string",
"include.unknown.datatypes": "true",
"key.converter": "io.confluent.connect.avro.AvroConverter",
"key.converter.basic.auth.credentials.source": "USER_INFO",
"key.converter.basic.auth.user.info": "${file:/etc/kafka/secrets/connect.properties:SR_USERNAME}:${file:/etc/kafka/secrets/connect.properties:SR_PASSWORD}",
"key.converter.schema.registry.url": "https://psrc-my.region.aws.confluent.cloud",
"name": "foo_prod:debezium_postgres_snapshot",
"plugin.name": "pgoutput",
"publication.name": "dbz_publication_snapshot",
"slot.name": "debezium_snapshot",
"snapshot.mode": "always",
"table.whitelist": "^jfinzel.test_broken_dbz$,^logical_ticker.tick$",
"tasks.max": "1",
"value.converter": "io.confluent.connect.avro.AvroConverter",
"value.converter.basic.auth.credentials.source": "USER_INFO",
"value.converter.basic.auth.user.info": "${file:/etc/kafka/secrets/connect.properties:SR_USERNAME}:${file:/etc/kafka/secrets/connect.properties:SR_PASSWORD}",
"value.converter.schema.registry.url": "https://psrc-my.region.aws.confluent.cloud"
},
"name": "foo_prod:debezium_postgres_snapshot",
"tasks": [
{
"connector": "foo_prod:debezium_postgres_snapshot",
"task": 0
}
],
"type": "source"
} {code}
Here is part of a slightly different stack trace at other times:
{code:java}
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m Exception in thread "pool-4-thread-1" java.lang.OutOfMemoryError: Java heap space2020-09-15 10:53:17,283 ERROR || [Worker clientId=connect-1, groupId=debezium-postgres-production] Heartbeat thread failed due to unexpected error [org.apache.kafka.clients.consumer.internals.AbstractCoordinator]
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m java.lang.OutOfMemoryError: Java heap space
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,283 ERROR || WorkerSourceTask{id=bar_prod:debezium_postgres-0} Failed to flush, timed out while waiting for producer to flush outstanding 259 messages [org.apache.kafka.connect.runtime.WorkerSourceTask]
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,284 INFO Postgres|foo_prod|postgres-connector-task Connected metrics set to 'false' [io.debezium.pipeline.metrics.StreamingChangeEventSourceMetrics]
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,284 WARN || [org.eclipse.jetty.util.thread.strategy.EatWhatYouKill]
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m java.lang.OutOfMemoryError: Java heap space
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m Exception in thread "pool-5-thread-1" java.lang.OutOfMemoryError: Java heap space
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m Exception in thread "KafkaBasedLog Work Thread - dbz_pg_connect_statuses" java.lang.OutOfMemoryError: Java heap space
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,283 INFO || [Producer clientId=connector-producer-foo_prod:debezium_postgres_snapshot-0] Closing the Kafka producer with timeoutMillis = 30000 ms. [org.apache.kafka.clients.producer.KafkaProducer]
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,284 ERROR || Unexpected exception in Thread[KafkaBasedLog Work Thread - dbz_pg_connect_offsets,5,main] [org.apache.kafka.connect.util.KafkaBasedLog]
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m java.lang.OutOfMemoryError: Java heap space
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,288 ERROR || WorkerSourceTask{id=bar_prod:debezium_postgres-0} Failed to commit offsets [org.apache.kafka.connect.runtime.SourceTaskOffsetCommitter]
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,288 INFO || WorkerSourceTask{id=foo_prod:debezium_postgres_snapshot-0} Committing offsets [org.apache.kafka.connect.runtime.WorkerSourceTask]
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,288 INFO || WorkerSourceTask{id=foo_prod:debezium_postgres_snapshot-0} flushing 0 outstanding messages for offset commit [org.apache.kafka.connect.runtime.WorkerSourceTask]
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,288 INFO || WorkerSourceTask{id=baz_prod:debezium_postgres-0} Committing offsets [org.apache.kafka.connect.runtime.WorkerSourceTask]
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,288 INFO || WorkerSourceTask{id=baz_prod:debezium_postgres-0} flushing 0 outstanding messages for offset commit [org.apache.kafka.connect.runtime.WorkerSourceTask]
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,284 WARN || [org.eclipse.jetty.util.thread.QueuedThreadPool]
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m java.lang.OutOfMemoryError: Java heap space
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m Exception in thread "DistributedHerder-connect-1-1" java.lang.OutOfMemoryError: Java heap space
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,284 ERROR || Uncaught exception in thread 'kafka-producer-network-thread | producer-3': [org.apache.kafka.common.utils.KafkaThread]
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m java.lang.OutOfMemoryError: Java heap space
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m 2020-09-15 10:53:17,287 ERROR || Uncaught exception in thread 'kafka-producer-network-thread | connector-producer-bar_prod:debezium_postgres-0': [org.apache.kafka.common.utils.KafkaThread]
Sep 15 05:53:17 dbz-pg01 docker-compose[50593]: #033[33mconnect_2 |#033[0m java.lang.OutOfMemoryError: Java heap space{code}
Contributor guide
Assessment
This issue has not been assessed yet.