Recommendations for slow broker startup

[PaulLiang1]

Hi,

We recently have a few broker that suffered a unclean shutdown, and it could take quite a bit of time (~hour) for a broker to come back up;

Usually these are the log lines that shown during startup.

• ...kafka Loading producer state from snapshot file...
• ...kafka Recovering unflushed segment...

Sometimes the this could exceed the duration of what liveness probe specifies, and cause the broker to stuck in a crash loop.
Current workaround is to keep increasing the value of initialDelaySeconds.

Question:

• Would increasing terminationGracePeriodSeconds help to reduce the likelihood of an unclean shutdown, so that there are less work required for broker startup hence making it faster?
• Is there a more elegant way of handling slow broker as setting initialDelaySeconds is more of a guess work. Would startupProbe more appropriate for such use case (even though Operator does not use this probe right now)?

Thanks,
Paul

[scholzj]

You do not mention what Strimzi version you use. I think that if you use a reasonably recent version of Strimzi you should not need to change any initial delays. And yes, if you think this happened because your broker is too busy when shutting down, you can try to increase the grace period (you can do it your self in the .spec.kafka.template section of the Kafka custom resource). But from my experience these things usually happen when the broker is killed for other reasons without any proper shutdown at all (node crash, storage failure etc.). But you would need to check the logs to see what exactly was the cause.

[forsberg]

I should mention this is my second Strimzi on AWS EKS cluster, this second one being at a different AWS region (and different job :) ) than the first one where I'm having this problem.

Being able to configure a startup probe could be another way forward.

[scholzj]

The startup probe basically just postpones the readiness probe. So it is not really something what solves this issue on its own. It just adds more timeouts to play with. The terminationGracePeriod is a bit tricky because you do not easily see if it is enough or not. We just had a discussion about it the other day, but without some good conclusion TBH.

[forsberg]

Although I agree that timeouts are usually just an indication that the problem has not been solved properly, if I compare the following two options:

• readinessProbe with 20 minutes of initial delay, and periodSeconds + failureThreshold that makes sense during normal operations to detect deadlocks etc.
• startupProbe with periodSeconds=10 and failureThreshold=120

..the latter has the advantage that it will mark the pod ready much faster during nominal startup, i.e when shutdown was clean, and I could keep readinessProbe at default values where it detects abnormal situations while the pod is running.

[danjo133]

I should mention this is my second Strimzi on AWS EKS cluster, this second one being at a different AWS region (and different job :) ) than the first one where I'm having this problem.

Yes, your old sins are now haunting me ;) I should follow your comments on github so I get a heads up for the upgrades I'm doing!

Being able to configure a startup probe could be another way forward.

I also stopped the operator to let the pods come alive (some 15+ minutes per pod). I saw various configurable delays, but am a bit unsure on what the best strategy is.

[jonerer]

I'm looking at the termination logs a cluster exhibiting this issue. Strimzi 0.22. The final lines in the shutdown operation seem to indicate an OK shutdown:

2022-01-13 14:20:27 +01:00 | production-kafka-2
2022-01-13 13:20:27,810 INFO [KafkaServer id=2] shut down completed (kafka.server.KafkaServer) [kafka-shutdown-hook]
2022-01-13 14:20:27 +01:00 | production-kafka-2
2022-01-13 13:20:27,805 INFO [SocketServer brokerId=2] Shutdown completed (kafka.network.SocketServer) [kafka-shutdown-hook]
2022-01-13 14:20:27 +01:00 | production-kafka-2
2022-01-13 13:20:27,792 INFO [SocketServer brokerId=2] Shutting down socket server (kafka.network.SocketServer) [kafka-shutdown-hook]
2022-01-13 14:20:27 +01:00 | production-kafka-2
2022-01-13 13:20:27,791 INFO [ThrottledChannelReaper-Request]: Shutdown completed (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [kafka-shutdown-hook]
2022-01-13 14:20:27 +01:00 | production-kafka-2
2022-01-13 13:20:27,791 INFO [ThrottledChannelReaper-Request]: Stopped (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [ThrottledChannelReaper-Request]
2022-01-13 14:20:26 +01:00 | production-kafka-2
2022-01-13 13:20:26,812 INFO [ThrottledChannelReaper-Produce]: Stopped (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [ThrottledChannelReaper-Produce]
2022-01-13 14:20:26 +01:00 | production-kafka-2
2022-01-13 13:20:26,812 INFO [ThrottledChannelReaper-Request]: Shutting down (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [kafka-shutdown-hook]
2022-01-13 14:20:26 +01:00 | production-kafka-2
2022-01-13 13:20:26,812 INFO [ThrottledChannelReaper-Produce]: Shutdown completed (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [kafka-shutdown-hook]
2022-01-13 14:20:26 +01:00 | production-kafka-2
2022-01-13 13:20:26,646 INFO [ThrottledChannelReaper-Fetch]: Shutdown completed (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [kafka-shutdown-hook]
2022-01-13 14:20:26 +01:00 | production-kafka-2
2022-01-13 13:20:26,646 INFO [ThrottledChannelReaper-Produce]: Shutting down (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [kafka-shutdown-hook]
2022-01-13 14:20:26 +01:00 | production-kafka-2
2022-01-13 13:20:26,646 INFO [ThrottledChannelReaper-Fetch]: Stopped (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [ThrottledChannelReaper-Fetch]
2022-01-13 14:20:26 +01:00 | production-kafka-2
2022-01-13 13:20:26,216 INFO [ThrottledChannelReaper-Fetch]: Shutting down (kafka.server.ClientQuotaManager$ThrottledChannelReaper) [kafka-shutdown-hook]
2022-01-13 14:20:26 +01:00 | production-kafka-2
2022-01-13 13:20:26,215 INFO Session: 0x201f854863b03f6 closed (org.apache.zookeeper.ZooKeeper) [kafka-shutdown-hook]
2022-01-13 14:20:26 +01:00 | production-kafka-2
2022-01-13 13:20:26,215 INFO channel is disconnected: [id: 0xc148bf50, L:/10.0.91.75:40568 ! R:production-zookeeper-client/172.20.22.45:2181] (org.apache.zookeeper.ClientCnxnSocketNetty) [nioEventLoopGroup-2-1]
2022-01-13 14:20:26 +01:00 | production-kafka-2
2022-01-13 13:20:26,215 INFO EventThread shut down for session: 0x201f854863b03f6 (org.apache.zookeeper.ClientCnxn) [main-EventThread]
2022-01-13 14:20:26 +01:00 | production-kafka-2
2022-01-13 13:20:26,215 INFO [ZooKeeperClient Kafka server] Closed. (kafka.zookeeper.ZooKeeperClient) [kafka-shutdown-hook]
2022-01-13 14:20:26 +01:00 | production-kafka-2
2022-01-13 13:20:26,215 INFO channel is told closing (org.apache.zookeeper.ClientCnxnSocketNetty) [nioEventLoopGroup-2-1]
2022-01-13 14:20:26 +01:00 | production-kafka-2
2022-01-13 13:20:26,214 INFO channel is told closing (org.apache.zookeeper.ClientCnxnSocketNetty) [kafka-shutdown-hook]
2022-01-13 14:20:26 +01:00 | production-kafka-2
2022-01-13 13:20:26,211 INFO [ZooKeeperClient Kafka server] Closing. (kafka.zookeeper.ZooKeeperClient) [kafka-shutdown-hook]
2022-01-13 14:20:26 +01:00 | production-kafka-2
2022-01-13 13:20:26,209 INFO [ReplicaStateMachine controllerId=2] Stopped replica state machine (kafka.controller.ZkReplicaStateMachine) [kafka-shutdown-hook]

etc... But the startup still takes ~20 minutes. Currently investigating whether our nodes are starved for bandwith to EBS or we're limited by disk type (currently using st1 on AWS, as indicated by https://aws.amazon.com/blogs/big-data/best-practices-for-running-apache-kafka-on-aws/)

The data folder for each broker is ~450GB. Is 20 minutes of startup time reasonable, given that shutdown was clean?

Also: Hello again @forsberg ! Did you get any further?