search

Alluxio / alluxio

Alluxio, data orchestration for analytics and machine learning in the cloud
https://www.alluxio.io
Apache License 2.0
6.86k stars 2.94k forks source link

Alluxio table attachdb / sync failed #12483

Closed hycsam closed 3 years ago

hycsam commented 4 years ago

Alluxio Env Version: 2.4.0 Master: -Xms96g -Xmx96g, Single master (no secondary, no standby), with embedded Journal server Worker: 10 worker nodes, each with -Xms4g -Xmx4g AWS Instance type: i3.4xlarge, 16cores, 120GB mem

Describe the bug I'm exploring Alluxio as a caching layer for our Presto cluster. All our files currently live in S3 and we are running Hive cluster upon those files. I'm using Alluxio Catalog Service solution to sync our Hive databases thru HMS to Alluxio master. It worked for small databases with 5 tables and a small number of partitions, but failed when I'm attaching a big DB with 20+ tables and nearly half of them have >20k partitions.

From the log I see Alluxio successfully attached small tables, then both RaftServer and AlluxioMasterProcess lost leadership, causing journal failed to flush. Alluxio then keeps retrying to flush the journal till timeout (or retry max reached), and then shutdown itself.

Here are the logs:

2020-11-10 02:30:32,498 INFO  Table - Creating new table events.screen_transition_counts_migrated with 1462 total partitions.
2020-11-10 02:30:33,540 INFO  Table - Creating new table events.invalid_events with 9379 total partitions.
2020-11-10 02:30:33,674 INFO  Database - Adding new table events.invalid_events
2020-11-10 02:30:33,713 INFO  RaftServerImpl - datapub-dev-alluxio-master.roles.service.robinhood_19200@group-ABB3109A44C1: changes role from    LEADER to FOLLOWER at term 93 for stepDown
2020-11-10 02:30:33,713 INFO  RoleInfo - datapub-dev-alluxio-master.roles.service.robinhood_19200: shutdown LeaderState
2020-11-10 02:30:33,713 INFO  PendingRequests - datapub-dev-alluxio-master.roles.service.robinhood_19200@group-ABB3109A44C1-PendingRequests: sendNotLeaderResponses
2020-11-10 02:30:33,713 INFO  AbstractPrimarySelector - Primary selector transitioning to SECONDARY
2020-11-10 02:30:33,714 INFO  RatisMetrics - Unregistering Metrics Registry : ratis.log_appender.datapub-dev-alluxio-master.roles.service.robinhood_19200@group-ABB3109A44C1
2020-11-10 02:30:33,714 INFO  BackupLeaderRole - Closing backup-leader role.
2020-11-10 02:30:33,714 INFO  BackupTracker - Resetting backup tracker.
2020-11-10 02:30:33,715 INFO  RatisMetrics - Unregistering Metrics Registry : ratis.server.datapub-dev-alluxio-master.roles.service.robinhood_19200@group-ABB3109A44C1
2020-11-10 02:30:33,716 INFO  RoleInfo - datapub-dev-alluxio-master.roles.service.robinhood_19200: start FollowerState
2020-11-10 02:30:33,725 INFO  Database - Adding new table events.screen_transition_counts_migrated
2020-11-10 02:30:33,736 INFO  AlluxioMasterProcess - Alluxio master ended (lost leadership)
2020-11-10 02:30:33,773 WARN  Database - Interrupted while waiting for db-sync thread pool to shut down. db: events
2020-11-10 02:30:33,775 ERROR AlluxioCatalog - Sync (during attach) failed for db 'events'.
java.io.IOException: Failed to sync database events. error: java.lang.RuntimeException: Thread was interrupted while waiting for invokeAll.
        at alluxio.master.table.Database.sync(Database.java:292)
        at alluxio.master.table.AlluxioCatalog.attachDatabase(AlluxioCatalog.java:126)
        at alluxio.master.table.DefaultTableMaster.attachDatabase(DefaultTableMaster.java:85)
        at alluxio.master.table.TableMasterClientServiceHandler.lambda$attachDatabase$0(TableMasterClientServiceHandler.java:74)
        at alluxio.RpcUtils.callAndReturn(RpcUtils.java:113)
        at alluxio.RpcUtils.call(RpcUtils.java:78)
        at alluxio.RpcUtils.call(RpcUtils.java:53)
        at alluxio.master.table.TableMasterClientServiceHandler.attachDatabase(TableMasterClientServiceHandler.java:72)
        at alluxio.grpc.table.TableMasterClientServiceGrpc$MethodHandlers.invoke(TableMasterClientServiceGrpc.java:1148)
        at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:172)
        at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
        at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
        at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
        at alluxio.security.authentication.AuthenticatedUserInjector$1.onHalfClose(AuthenticatedUserInjector.java:67)
        at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:331)
        at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:817)
        at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
        at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
        at alluxio.concurrent.jsr.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1378)
        at alluxio.concurrent.jsr.ForkJoinTask.doExec(ForkJoinTask.java:609)
        at alluxio.concurrent.jsr.ForkJoinPool.runWorker(ForkJoinPool.java:1356)
        at alluxio.concurrent.jsr.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:131)
Caused by: java.lang.RuntimeException: Thread was interrupted while waiting for invokeAll.
        at alluxio.util.CommonUtils.invokeAll(CommonUtils.java:583)
        at alluxio.master.table.Database.sync(Database.java:290)
        ... 21 more
2020-11-10 02:30:33,775 ERROR Database - Sync thread failed for events.full_event
alluxio.exception.status.UnavailableException: Failed after 1 attempts: alluxio.exception.status.CancelledException: HTTP/2 error code: CANCEL
Received Rst Stream
        at alluxio.AbstractClient.retryRPCInternal(AbstractClient.java:416)
        at alluxio.AbstractClient.retryRPC(AbstractClient.java:365)
        at alluxio.client.file.RetryHandlingFileSystemMasterClient.reverseResolve(RetryHandlingFileSystemMasterClient.java:272)
        at alluxio.client.file.BaseFileSystem.lambda$reverseResolve$14(BaseFileSystem.java:378)
        at alluxio.client.file.BaseFileSystem.rpc(BaseFileSystem.java:519)
        at alluxio.client.file.BaseFileSystem.reverseResolve(BaseFileSystem.java:377)
        at alluxio.table.common.udb.UdbUtils.mountAlluxioPath(UdbUtils.java:56)
        at alluxio.table.under.hive.HiveDatabase.mountAlluxioPaths(HiveDatabase.java:176)
        at alluxio.table.under.hive.HiveDatabase.getTable(HiveDatabase.java:230)
        at alluxio.master.table.Database.lambda$sync$0(Database.java:231)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: alluxio.exception.status.CancelledException: HTTP/2 error code: CANCEL
Received Rst Stream
        at alluxio.exception.status.AlluxioStatusException.from(AlluxioStatusException.java:129)
        at alluxio.exception.status.AlluxioStatusException.fromStatusRuntimeException(AlluxioStatusException.java:214)
        at alluxio.AbstractClient.retryRPCInternal(AbstractClient.java:401)
        ... 13 more
Caused by: io.grpc.StatusRuntimeException: CANCELLED: HTTP/2 error code: CANCEL
Received Rst Stream
        at io.grpc.stub.ClientCalls.toStatusRuntimeException(ClientCalls.java:240)
        at io.grpc.stub.ClientCalls.getUnchecked(ClientCalls.java:221)
        at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:140)
        at alluxio.grpc.FileSystemMasterClientServiceGrpc$FileSystemMasterClientServiceBlockingStub.reverseResolve(FileSystemMasterClientServiceGrpc.java:1707)
        at alluxio.client.file.RetryHandlingFileSystemMasterClient.lambda$reverseResolve$18(RetryHandlingFileSystemMasterClient.java:272)
        at alluxio.AbstractClient.retryRPCInternal(AbstractClient.java:399)
        ... 13 more
2020-11-10 02:30:33,778 WARN  MasterJournalContext - Journal flush failed. retrying...
alluxio.exception.status.AlluxioStatusException
        at alluxio.master.journal.AsyncJournalWriter.flush(AsyncJournalWriter.java:352)
        at alluxio.master.journal.MasterJournalContext.waitForJournalFlush(MasterJournalContext.java:75)
        at alluxio.master.journal.MasterJournalContext.close(MasterJournalContext.java:91)
        at alluxio.master.journal.StateChangeJournalContext.close(StateChangeJournalContext.java:53)
        at alluxio.master.table.DefaultTableMaster.attachDatabase(DefaultTableMaster.java:87)
        at alluxio.master.table.TableMasterClientServiceHandler.lambda$attachDatabase$0(TableMasterClientServiceHandler.java:74)
        at alluxio.RpcUtils.callAndReturn(RpcUtils.java:113)
        at alluxio.RpcUtils.call(RpcUtils.java:78)
        at alluxio.RpcUtils.call(RpcUtils.java:53)
        at alluxio.master.table.TableMasterClientServiceHandler.attachDatabase(TableMasterClientServiceHandler.java:72)
        at alluxio.grpc.table.TableMasterClientServiceGrpc$MethodHandlers.invoke(TableMasterClientServiceGrpc.java:1148)
        at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:172)
        at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
        at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
        at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
        at alluxio.security.authentication.AuthenticatedUserInjector$1.onHalfClose(AuthenticatedUserInjector.java:67)
        at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:331)
        at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:817)
        at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
        at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
        at alluxio.concurrent.jsr.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1378)
        at alluxio.concurrent.jsr.ForkJoinTask.doExec(ForkJoinTask.java:609)
        at alluxio.concurrent.jsr.ForkJoinPool.runWorker(ForkJoinPool.java:1356)
        at alluxio.concurrent.jsr.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:131)
Caused by: java.lang.InterruptedException
        at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:521)
        at com.google.common.util.concurrent.AbstractFuture$TrustedFuture.get(AbstractFuture.java:102)
        at alluxio.master.journal.AsyncJournalWriter$FlushTicket.block(AsyncJournalWriter.java:97)
        at alluxio.concurrent.jsr.ForkJoinPool.managedBlock(ForkJoinPool.java:1005)
        at alluxio.concurrent.ForkJoinPoolHelper.safeManagedBlock(ForkJoinPoolHelper.java:41)
        at alluxio.master.journal.AsyncJournalWriter$FlushTicket.waitCompleted(AsyncJournalWriter.java:88)
        at alluxio.master.journal.AsyncJournalWriter.flush(AsyncJournalWriter.java:349)
        ... 23 more
.......
2020-11-10 02:35:34,129 ERROR MasterJournalContext - Fatal error: Journal flush failed after 1597 attempts

To Reproduce ./bin/alluxio table attachdb hive thrift://HMS_HOST:HMS_PORT DB_NAME --ignore-sync-errors -o catalog.db.ignore.udb.tables=TABLES_TO_IGNORE -o catalog.db.sync.threads=10

Expected behavior The command line prompt will stuck there for ~5min and whole Alluxio cluster shutdown

Urgency The DB I tried attaching is of medium size among all our Hive databases, and we need to migrate ~250 databases. This is blocking us from testing Presto queries with Alluxio catalog.

HelloHorizon commented 4 years ago

Related Issue #12356 .

calvinjia commented 4 years ago

@hycsam Thanks for opening this issue. This is potentially linked to #12356 .

apc999 commented 3 years ago

identified issue in embedded journal. let's aim to fix this issue in the next release @calvinjia

apc999 commented 3 years ago

@gpang @LuQQiu will https://github.com/Alluxio/alluxio/pull/12650 resolve this issue?

LuQQiu commented 3 years ago

This issue is similar to #12356 and may be solved by #12658 I am now validating the #12658 and see if any further changes are needed

LuQQiu commented 3 years ago

PR #12649 helps Alluxio log the correct Ratis error that helps to debug the related journal issues.

PR #12650 expose Ratis journal size related configuration to Alluxio configuration and enlarge those values to support journaling entries larger than 3MB. Note that this is mainly helping the Ratis journal write path. Ratis journal read path has a hard limit of 30MB per entry.

PR #12658 change from logging a table with all its partitions to logging a table entry and multiple partitions entries based on alluxio.table.journal.partitions.chunk.size (=500 by default, a single entry only contains up to 500 partitions). In the future, Journal restore or restart will not be crashed by large table entries anymore.

PR #12695 helps resolve or prevents unexpected large journal entries coming from other places of Alluxio by flushing journal entries bigger than MASTER_EMBEDDED_JOURNAL_ENTRY_SIZE_MAX / 3 and log error when journal entries bigger than the MASTER_EMBEDDED_JOURNAL_ENTRY_SIZE_MAX.

@hycsam The latest Alluxio master github branch contains the fixes. Could you help validate if the fixes are enough to solve the issue? Appreciate, if you help any questions regarding the fixes and validation, feel free to contact us on slack or directly in this ticket.

hycsam commented 3 years ago

@LuQQiu Thanks for the fix, validated the issue has been resolved! Closing the ticket